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
does generate a *lot* of log output, including complete dumps of the
databases. Normally it is not necessary to enable debug so I have not looked
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 not
forgotten. Thanks for the report
Chris
--------------
Full message:
Hi,
just made the regular daily update (well, this time after it was suspendet
for some edays) and noticed ap's running very slow, with pauses between
every download (which run at normal speed themwselves) and sometimes
even within a single download.
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:
2005/12/12 13:14 CET [FetcherHttp,client]
[db] /debian/pool/main/o/openssh/openssh-server_4.2p1-5_i386.deb
2005/12/12 13:14 CET [FetcherHttp,client] [db] gstreamer0.8-ffmpeg:
2005/12/12 13:14 CET [FetcherHttp,client]
[db] /debian/pool/main/g/gst-ffmpeg/gstreamer0.8-ffmpeg_0.8.5-2_i386.deb
2005/12/12 13:14 CET [FetcherHttp,client]
[db] /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:
2005/12/12 13:14 CET [FetcherHttp,client]
[db] /debian/pool/main/b/binutils/binutils_2.15-6_i386.deb
2005/12/12 13:14 CET [FetcherHttp,client]
[db] /debian/pool/main/b/binutils/binutils_2.16.1-2_i386.deb
2005/12/12 13:14 CET [FetcherHttp,client]
[db] /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
clientConnectionLost
2005/12/12 13:14 CET [FetcherHttp,client] Stopping factory
<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] 282 WeakKeyDictionary
2005/12/12 13:14 CET [Channel,73,127.0.0.1] 94 Exception
2005/12/12 13:14 CET [Channel,73,127.0.0.1] 32 DBError
2005/12/12 13:14 CET [Channel,73,127.0.0.1] 31 SelectReactor
2005/12/12 13:14 CET [Channel,73,127.0.0.1] 28
ProtocolToConsumerAdapter
2005/12/12 13:14 CET [Channel,73,127.0.0.1] 28 DBError
2005/12/12 13:14 CET [Channel,73,127.0.0.1] 26 Protocol
2005/12/12 13:14 CET [Channel,73,127.0.0.1] 24 StandardError
2005/12/12 13:14 CET [Channel,73,127.0.0.1] 17 Warning
2005/12/12 13:14 CET [Channel,73,127.0.0.1] 17 ValueError
Apparently, ap2 was busy with recreating (? or whatever) the database
in the background. This is only an AMD K6 (500mhz) with 512MB, but
anything is fully optimized and it's rarely grunting under load. But i
suspect
a bottleneck somewhere. I set debug = all:9 db:0, restarted ap, and bingo it
worked fast as usual again. After some 20 packages i interrupted the update
agian, and here are the last logline:
(...)
2005/12/12 13:28 CET [Channel,28,127.0.0.1] [Fetcher.activate] (debian)
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
<apt_proxy.apt_proxy.ClientFactory instance at 0xb6adc1cc>
2005/12/12 13:28 CET [Uninitialized] [http_client]
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 Dec
2005 12:28:56 GMT
2005/12/12 13:28 CET [FetcherHttp,client] [debug] Received: Server
Apache/2.0.54 (Debian GNU/Linux)
2005/12/12 13:28 CET [FetcherHttp,client] [debug] Received: Last-Modified Mon,
28 Nov 2005 22:02:07 GMT
2005/12/12 13:28 CET [FetcherHttp,client] [debug] Received: ETag
"165c084-23470-410515c0"
2005/12/12 13:28 CET [FetcherHttp,client] [debug] Received: Accept-Ranges
bytes
2005/12/12 13:28 CET [FetcherHttp,client] [debug] Received: Content-Length
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
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] 274 WeakKeyDictionary
2005/12/12 13:28 CET [Channel,28,127.0.0.1] 93 Exception
2005/12/12 13:28 CET [Channel,28,127.0.0.1] 32 DBError
2005/12/12 13:28 CET [Channel,28,127.0.0.1] 28 DBError
2005/12/12 13:28 CET [Channel,28,127.0.0.1] 27 SelectReactor
2005/12/12 13:28 CET [Channel,28,127.0.0.1] 26 Protocol
2005/12/12 13:28 CET [Channel,28,127.0.0.1] 24 StandardError
2005/12/12 13:28 CET [Channel,28,127.0.0.1] 24
ProtocolToConsumerAdapter
2005/12/12 13:28 CET [Channel,28,127.0.0.1] 17 Warning
2005/12/12 13:28 CET [Channel,28,127.0.0.1] 17 ValueError
2005/12/12 13:28 CET [FetcherHttp,client] [Fetcher] Finished receiving data,
status:200 saveData:1
2005/12/12 13:29 CET [FetcherHttp,client] [max_versions] [['0.23.4-8',
'/debian/pool/main/d/dbus/python2.3-dbus_0.23.4-8_i386.deb'], ['0.23.4-7',
'/debian/pool/main/d/dbus/python2.3-dbus_0.23.4-7_i386.deb'], ['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] [apt_pkg] No Packages files
available for cyril backend
2005/12/12 13:29 CET [FetcherHttp,client] [apt_pkg] No Packages files
available for java backend
2005/12/12 13:29 CET [FetcherHttp,client] [apt_pkg] No Packages files
available for videolan backend
2005/12/12 13:29 CET [FetcherHttp,client] [max_versions] Current Versions:
[('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]
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
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
clientConnectionLost
2005/12/12 13:29 CET [FetcherHttp,client] Stopping factory
<apt_proxy.apt_proxy.ClientFactory instance at 0xb6adc1cc>
But was the database process also running time ? I didn't know how to
determine that. So i tried with debug = all:9 again to see if it would run
slow again. I couldn't see any database activity this time, it just said,
2005/12/12 13:44 CET [-] [debug] Verifying
database: /var/cache/apt-proxy/.apt-proxy/db/access.db
2005/12/12 13:44 CET [-] [debug] Opening
database /var/cache/apt-proxy/.apt-proxy/db/access.db
and that's all. But hey, the database activity started immediately again
when the update continued again ! Like shown above, it went through all
kind of packages which are completely unrelated to the actual update.
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:
2005/12/12 13:50 CET [FetcherHttp,client]
[db] /debian/pool/main/g/gst-ffmpeg/gstreamer0.8-ffmpeg_0.8.5-2_i386.deb
2005/12/12 13:50 CET [FetcherHttp,client]
[db] /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:
2005/12/12 13:50 CET [FetcherHttp,client]
[db] /debian/pool/main/b/binutils/binutils_2.15-6_i386.deb
2005/12/12 13:50 CET [FetcherHttp,client]
[db] /debian/pool/main/b/binutils/binutils_2.16.1-2_i386.deb
2005/12/12 13:50 CET [FetcherHttp,client]
[db] /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
clientConnectionLost
2005/12/12 13:50 CET [FetcherHttp,client] Stopping factory
<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] 265 WeakKeyDictionary
2005/12/12 13:50 CET [Channel,14,127.0.0.1] 93 Exception
2005/12/12 13:50 CET [Channel,14,127.0.0.1] 41 SelectReactor
2005/12/12 13:50 CET [Channel,14,127.0.0.1] 32 DBError
2005/12/12 13:50 CET [Channel,14,127.0.0.1] 28 DBError
2005/12/12 13:50 CET [Channel,14,127.0.0.1] 26 Protocol
2005/12/12 13:50 CET [Channel,14,127.0.0.1] 24 StandardError
2005/12/12 13:50 CET [Channel,14,127.0.0.1] 20 DelayedCall
2005/12/12 13:50 CET [Channel,14,127.0.0.1] 20
ProtocolToConsumerAdapter
2005/12/12 13:50 CET [Channel,14,127.0.0.1] 17 Warning
I wonder if the db debug level triggers a whole db lookup which somehow's
using up rather much resources (both hd and cpu) ?
This is ap 19.x, debian testing/unstable, kernel 2.6.13 with a
low-latency-desktop kernel (*)
HTH,
micha
*) The respective description of the kernel source is,
CONFIG_PREEMPT:
This option reduces the latency of the kernel by making
all kernel code (that is not executing in a critical section)
preemptible. This allows reaction to interactive events by
permitting a low priority process to be preempted involuntarily
even if it is in kernel mode executing a system call and would
otherwise not be about to reach a natural preemption point.
This allows applications to run more 'smoothly' even when the
system is under load, at the cost of slighly lower throughput
and a slight runtime overhead to kernel code.
Select this if you are building a kernel for a desktop or
embedded system with latency requirements in the milliseconds
range.
