[Apt-proxy-users] apt-proxy: heavy resource usage when database debugging is on

[Chris H. <ha...@de...>]

Package: apt-proxy
Version: 1.9.32
Severity: minor

Hi

On Monday 12 Dec 2005 12:56, Micha wrote:
> I wonder if the db debug level triggers a whole db lookup which somehow's
> using up rather much resources (both hd and cpu) ?

I think your analysis is exactly right. running the database at full debug=
=20
does generate a *lot* of log output, including complete dumps of the=20
databases. Normally it is not necessary to enable debug so I have not looke=
d=20
at optimising this.

> This is ap 19.x, debian testing/unstable, kernel 2.6.13 with a
> low-latency-desktop kernel (*)

Maybe this makes the usage worse. I am opening a bug to make sure this is n=
ot=20
forgotten. Thanks for the report

Chris

=2D-------------
=46ull message:

Hi,

just made the regular daily update (well, this time after it was suspendet=
=20
for some edays) and noticed ap's running very slow, with pauses between=20
every download (which run at normal speed themwselves) and sometimes=20
even within a single download.=20
Parallel streaming is _not_ enabled in the config.

After 60 packages or so i interrupted the update.
Debug level was all:9 so i got some logging (last lines):


(...)
2005/12/12 13:14 CET [FetcherHttp,client] [db] openssh-server:=20
2005/12/12 13:14 CET [FetcherHttp,client]=20
[db] =A0/debian/pool/main/o/openssh/openssh-server_4.2p1-5_i386.deb
2005/12/12 13:14 CET [FetcherHttp,client] [db] gstreamer0.8-ffmpeg:=20
2005/12/12 13:14 CET [FetcherHttp,client]=20
[db] =A0/debian/pool/main/g/gst-ffmpeg/gstreamer0.8-ffmpeg_0.8.5-2_i386.deb
2005/12/12 13:14 CET [FetcherHttp,client]=20
[db] =A0/debian/pool/main/g/gst-ffmpeg/gstreamer0.8-ffmpeg_0.8.7-4_i386.deb
2005/12/12 13:14 CET [FetcherHttp,client] [db] binutils:=20
2005/12/12 13:14 CET [FetcherHttp,client]=20
[db] =A0/debian/pool/main/b/binutils/binutils_2.15-6_i386.deb
2005/12/12 13:14 CET [FetcherHttp,client]=20
[db] =A0/debian/pool/main/b/binutils/binutils_2.16.1-2_i386.deb
2005/12/12 13:14 CET [FetcherHttp,client]=20
[db] =A0/debian/pool/main/b/binutils/binutils_2.16.1cvs20051117-1_i386.deb

2005/12/12 13:14 CET [FetcherHttp,client] [Fetcher] Last request removed

2005/12/12 13:14 CET [FetcherHttp,client] [http-client] XXX=20
clientConnectionLost
2005/12/12 13:14 CET [FetcherHttp,client] Stopping factory=20
<apt_proxy.apt_proxy.ClientFactory instance at 0xb6a5d88c>
2005/12/12 13:14 CET [Channel,73,127.0.0.1] [debug] Client connection closed
2005/12/12 13:14 CET [Channel,73,127.0.0.1] Top 10:
2005/12/12 13:14 CET [Channel,73,127.0.0.1] =A0 =A0 =A0 =A0282 WeakKeyDicti=
onary
2005/12/12 13:14 CET [Channel,73,127.0.0.1] =A0 =A0 =A0 =A0 94 Exception
2005/12/12 13:14 CET [Channel,73,127.0.0.1] =A0 =A0 =A0 =A0 32 DBError
2005/12/12 13:14 CET [Channel,73,127.0.0.1] =A0 =A0 =A0 =A0 31 SelectReactor
2005/12/12 13:14 CET [Channel,73,127.0.0.1] =A0 =A0 =A0 =A0 28=20
ProtocolToConsumerAdapter
2005/12/12 13:14 CET [Channel,73,127.0.0.1] =A0 =A0 =A0 =A0 28 DBError
2005/12/12 13:14 CET [Channel,73,127.0.0.1] =A0 =A0 =A0 =A0 26 Protocol
2005/12/12 13:14 CET [Channel,73,127.0.0.1] =A0 =A0 =A0 =A0 24 StandardError
2005/12/12 13:14 CET [Channel,73,127.0.0.1] =A0 =A0 =A0 =A0 17 Warning
2005/12/12 13:14 CET [Channel,73,127.0.0.1] =A0 =A0 =A0 =A0 17 ValueError



Apparently, ap2 was busy with recreating (? or whatever) the database=20
in the background. This is only an AMD K6 (500mhz) with 512MB, but=20
anything is fully optimized and it's rarely grunting under load. =A0But i=20
suspect=20
a bottleneck somewhere. I set debug =3D all:9 db:0, restarted ap, and bingo=
 it=20
worked fast as usual again. After some 20 packages i interrupted the update=
=20
agian, and here are the last logline:



(...)
2005/12/12 13:28 CET [Channel,28,127.0.0.1] [Fetcher.activate] (debian)=20
servers:1/debian/pool/main/d/dbus/python2.3-dbus_0.23.4-8_i386.deb
2005/12/12 13:28 CET [Channel,28,127.0.0.1] Starting factory=20
<apt_proxy.apt_proxy.ClientFactory instance at 0xb6adc1cc>
2005/12/12 13:28 CET [Uninitialized] [http_client]=20
GET:/debian/pool/main/d/dbus/python2.3-dbus_0.23.4-8_i386.deb
2005/12/12 13:28 CET [Uninitialized] [http_client] host:ftp2.de.debian.org
2005/12/12 13:28 CET [FetcherHttp,client] [http_client] handleStatus 200 - =
OK
2005/12/12 13:28 CET [FetcherHttp,client] [debug] Received: Date Mon, 12 De=
c=20
2005 12:28:56 GMT
2005/12/12 13:28 CET [FetcherHttp,client] [debug] Received: Server=20
Apache/2.0.54 (Debian GNU/Linux)
2005/12/12 13:28 CET [FetcherHttp,client] [debug] Received: Last-Modified M=
on,=20
28 Nov 2005 22:02:07 GMT
2005/12/12 13:28 CET [FetcherHttp,client] [debug] Received: ETag=20
"165c084-23470-410515c0"
2005/12/12 13:28 CET [FetcherHttp,client] [debug] Received: Accept-Ranges=20
bytes
2005/12/12 13:28 CET [FetcherHttp,client] [debug] Received: Content-Length=
=20
144496
2005/12/12 13:28 CET [FetcherHttp,client] [debug] Received: Connection close
2005/12/12 13:28 CET [FetcherHttp,client] [debug] Received: Content-Type=20
application/x-debian-package
2005/12/12 13:28 CET [Channel,28,127.0.0.1] [Fetcher] Last request removed
2005/12/12 13:28 CET [Channel,28,127.0.0.1] [debug] Client connection closed
2005/12/12 13:28 CET [Channel,28,127.0.0.1] Top 10:
2005/12/12 13:28 CET [Channel,28,127.0.0.1] =A0 =A0 =A0 =A0274 WeakKeyDicti=
onary
2005/12/12 13:28 CET [Channel,28,127.0.0.1] =A0 =A0 =A0 =A0 93 Exception
2005/12/12 13:28 CET [Channel,28,127.0.0.1] =A0 =A0 =A0 =A0 32 DBError
2005/12/12 13:28 CET [Channel,28,127.0.0.1] =A0 =A0 =A0 =A0 28 DBError
2005/12/12 13:28 CET [Channel,28,127.0.0.1] =A0 =A0 =A0 =A0 27 SelectReactor
2005/12/12 13:28 CET [Channel,28,127.0.0.1] =A0 =A0 =A0 =A0 26 Protocol
2005/12/12 13:28 CET [Channel,28,127.0.0.1] =A0 =A0 =A0 =A0 24 StandardError
2005/12/12 13:28 CET [Channel,28,127.0.0.1] =A0 =A0 =A0 =A0 24=20
ProtocolToConsumerAdapter
2005/12/12 13:28 CET [Channel,28,127.0.0.1] =A0 =A0 =A0 =A0 17 Warning
2005/12/12 13:28 CET [Channel,28,127.0.0.1] =A0 =A0 =A0 =A0 17 ValueError
2005/12/12 13:28 CET [FetcherHttp,client] [Fetcher] Finished receiving data=
,=20
status:200 saveData:1
2005/12/12 13:29 CET [FetcherHttp,client] [max_versions] [['0.23.4-8',=20
'/debian/pool/main/d/dbus/python2.3-dbus_0.23.4-8_i386.deb'], ['0.23.4-7',=
=20
'/debian/pool/main/d/dbus/python2.3-dbus_0.23.4-7_i386.deb'], ['0.23.4-1',=
=20
'/debian/pool/main/d/dbus/python2.3-dbus_0.23.4-1_i386.deb']]
2005/12/12 13:29 CET [FetcherHttp,client] [apt_pkg] No Packages files=20
available for cyril backend
2005/12/12 13:29 CET [FetcherHttp,client] [apt_pkg] No Packages files=20
available for java backend
2005/12/12 13:29 CET [FetcherHttp,client] [apt_pkg] No Packages files=20
available for videolan backend
2005/12/12 13:29 CET [FetcherHttp,client] [max_versions] Current Versions:=
=20
[('0.23.4-1', 'debian/pool/main/d/dbus/python2.3-dbus_0.23.4-1_i386.deb')]
2005/12/12 13:29 CET [FetcherHttp,client] [max_versions]=20
Deleting /var/cache/apt-proxy//debian/pool/main/d/dbus/python2.3-dbus_0.23.=
4-7_i386.deb
2005/12/12 13:29 CET [FetcherHttp,client] [max_versions] reset at=20
debian/pool/main/d/dbus/python2.3-dbus_0.23.4-1_i386.deb
2005/12/12 13:29 CET [FetcherHttp,client] [http-client] XXX=20
clientConnectionLost
2005/12/12 13:29 CET [FetcherHttp,client] Stopping factory=20
<apt_proxy.apt_proxy.ClientFactory instance at 0xb6adc1cc>




But was the database process also running time ? I didn't know how to=20
determine that. So i tried with debug =3D all:9 again to see if it would ru=
n=20
slow again. I couldn't see any database activity this time, it just said,

2005/12/12 13:44 CET [-] [debug] Verifying=20
database: /var/cache/apt-proxy/.apt-proxy/db/access.db
2005/12/12 13:44 CET [-] [debug] Opening=20
database /var/cache/apt-proxy/.apt-proxy/db/access.db

and that's all. But hey, the database activity started immediately again=20
when the update continued again ! Like shown above, it went through all=20
kind of packages which are completely unrelated to the actual update.=20
And again the download/serving was heavily disrupted.



The last loglines until finishing were:

2005/12/12 13:50 CET [FetcherHttp,client] [db] gstreamer0.8-ffmpeg:=20
2005/12/12 13:50 CET [FetcherHttp,client]=20
[db] =A0/debian/pool/main/g/gst-ffmpeg/gstreamer0.8-ffmpeg_0.8.5-2_i386.deb
2005/12/12 13:50 CET [FetcherHttp,client]=20
[db] =A0/debian/pool/main/g/gst-ffmpeg/gstreamer0.8-ffmpeg_0.8.7-4_i386.deb
2005/12/12 13:50 CET [FetcherHttp,client] [db] binutils:=20
2005/12/12 13:50 CET [FetcherHttp,client]=20
[db] =A0/debian/pool/main/b/binutils/binutils_2.15-6_i386.deb
2005/12/12 13:50 CET [FetcherHttp,client]=20
[db] =A0/debian/pool/main/b/binutils/binutils_2.16.1-2_i386.deb
2005/12/12 13:50 CET [FetcherHttp,client]=20
[db] =A0/debian/pool/main/b/binutils/binutils_2.16.1cvs20051117-1_i386.deb
2005/12/12 13:50 CET [FetcherHttp,client] [Fetcher] Last request removed
2005/12/12 13:50 CET [FetcherHttp,client] [http-client] XXX=20
clientConnectionLost
2005/12/12 13:50 CET [FetcherHttp,client] Stopping factory=20
<apt_proxy.apt_proxy.ClientFactory instance at 0xb5831e6c>
2005/12/12 13:50 CET [Channel,14,127.0.0.1] [debug] Client connection closed
2005/12/12 13:50 CET [Channel,14,127.0.0.1] Top 10:
2005/12/12 13:50 CET [Channel,14,127.0.0.1] =A0 =A0 =A0 =A0265 WeakKeyDicti=
onary
2005/12/12 13:50 CET [Channel,14,127.0.0.1] =A0 =A0 =A0 =A0 93 Exception
2005/12/12 13:50 CET [Channel,14,127.0.0.1] =A0 =A0 =A0 =A0 41 SelectReactor
2005/12/12 13:50 CET [Channel,14,127.0.0.1] =A0 =A0 =A0 =A0 32 DBError
2005/12/12 13:50 CET [Channel,14,127.0.0.1] =A0 =A0 =A0 =A0 28 DBError
2005/12/12 13:50 CET [Channel,14,127.0.0.1] =A0 =A0 =A0 =A0 26 Protocol
2005/12/12 13:50 CET [Channel,14,127.0.0.1] =A0 =A0 =A0 =A0 24 StandardError
2005/12/12 13:50 CET [Channel,14,127.0.0.1] =A0 =A0 =A0 =A0 20 DelayedCall
2005/12/12 13:50 CET [Channel,14,127.0.0.1] =A0 =A0 =A0 =A0 20=20
ProtocolToConsumerAdapter
2005/12/12 13:50 CET [Channel,14,127.0.0.1] =A0 =A0 =A0 =A0 17 Warning




I wonder if the db debug level triggers a whole db lookup which somehow's=20
using up rather much resources (both hd and cpu) ?
This is ap 19.x, debian testing/unstable, kernel 2.6.13 with a=20
low-latency-desktop kernel (*)

HTH,=20

micha


*) The respective description of the kernel source is,=20

=A0CONFIG_PREEMPT: =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =
=A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=
 =A0 =A0 =A0 =A0=20
=A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=
 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =
=A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=20
=A0 =A0 This option reduces the latency of the kernel by making =A0 =A0 =A0=
 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=20
=A0 =A0 all kernel code (that is not executing in a critical section) =A0 =
=A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=20
=A0 =A0 preemptible. =A0This allows reaction to interactive events by =A0 =
=A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=20
=A0 =A0 permitting a low priority process to be preempted involuntarily =A0=
 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=20
=A0 =A0 even if it is in kernel mode executing a system call and would =A0 =
=A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0
=A0 =A0 otherwise not be about to reach a natural preemption point. =A0 =A0=
 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=20
=A0 =A0 This allows applications to run more 'smoothly' even when the =A0 =
=A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=20
=A0 =A0 system is under load, at the cost of slighly lower throughput =A0 =
=A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=20
=A0 =A0 and a slight runtime overhead to kernel code. =A0 =A0 =A0 =A0 =A0 =
=A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=20
=A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=
 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =
=A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=20
=A0 =A0 Select this if you are building a kernel for a desktop or =A0 =A0 =
=A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=20
=A0 =A0 embedded system with latency requirements in the milliseconds =A0 =
=A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=20
=A0 =A0 range. =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =
=A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=
 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0