Menu
▾
▴
[Apt-proxy-users] debug level triggering database lookup, causing download discontinuity ?
|
From: Micha <ear...@gm...> - 2005-12-12 12:57:12
|
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. |