Your message dated Tue, 25 Sep 2012 20:47:37 +0000 with message-id <[email protected]> and subject line Bug#672871: fixed in apt-cacher 1.7.5 has caused the Debian Bug report #672871, regarding apt-cacher: libcurl thread uses too much CPU time to be marked as done.
This means that you claim that the problem has been dealt with. If this is not the case it is now your responsibility to reopen the Bug report if necessary, and/or fix the problem forthwith. (NB: If you are a system administrator and have no idea what this message is talking about, this may indicate a serious mail system misconfiguration somewhere. Please contact [email protected] immediately.) -- 672871: http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=672871 Debian Bug Tracking System Contact [email protected] with problems
--- Begin Message ---Package: apt-cacher Version: 1.7.4 Severity: normal Tags: patch The 'libcurl' thread spawned by apt-cacher to manage downloads is using too much CPU time on my machine. I noticed just by chance that it easily reaches 80-90% of sustained (not peak) usage during downloads. This is the process in the 'ps' output: www-data 4967 68.8 0.4 132112 18588 ? R 10:36 0:05 /usr/sbin/apt-cacher [libcurl] First of all I measured the CPU usage of the running process for statistical purposes. I sampled CPU usage 100 times with 1 second delay during a normal 'aptitude update' from a single client. This is the result: $ pidstat -p 4967 1 100 Linux 3.3.6 (alan) 05/14/2012 _x86_64_ (4 CPU) 10:36:44 AM PID %usr %system %guest %CPU CPU Command 10:36:45 AM 4967 90.00 2.00 0.00 92.00 2 /usr/sbin/apt-c 10:36:46 AM 4967 93.00 2.00 0.00 95.00 0 /usr/sbin/apt-c 10:36:47 AM 4967 91.00 2.00 0.00 93.00 0 /usr/sbin/apt-c 10:36:48 AM 4967 94.00 2.00 0.00 96.00 2 /usr/sbin/apt-c ... [cut many similar lines] ... 10:38:21 AM 4967 94.00 1.00 0.00 95.00 0 /usr/sbin/apt-c 10:38:22 AM 4967 95.00 0.00 0.00 95.00 0 /usr/sbin/apt-c 10:38:23 AM 4967 94.00 2.00 0.00 96.00 2 /usr/sbin/apt-c 10:38:24 AM 4967 93.00 2.00 0.00 95.00 2 /usr/sbin/apt-c Average: 4967 88.97 1.76 0.00 90.73 - /usr/sbin/apt-c As you can see the average value for 100 seconds is really high. It is definitely too much for this processor class, also considering what that process has to do. To investigate further I used 'strace' and after attaching to the process I noticed that it does almost nothing: it sits most of the time in a very tight poll-select loop, as you can see from this excerpt of the output: ... poll([{fd=2, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout) select(8, [0], NULL, NULL, {0, 10}) = 0 (Timeout) poll([{fd=2, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout) select(8, [0], NULL, NULL, {0, 10}) = 0 (Timeout) ... I don't have the full picture of the structure of the source code for apt-cacher in my head, nonetheless I started to read it, searching for calls to 'select'. I found one line that I considered interesting in relation to this misbehavior and patched it like this: --- apt-cacher 2012-05-14 10:42:44.883660541 +0200 +++ apt-cacher.new 2012-05-14 10:43:34.063658230 +0200 @@ -1480,7 +1480,7 @@ # timeout here which also prevents the parent while # loop from running too fast and hogging the CPU # uselessly. - if ($active_handles && $select->can_read(0.00001)) { + if ($active_handles && $select->can_read(0.1)) { $cfg->{debug} && debug_message('Pending connection'); next LIBCURL_REQUEST; } As you can see I just increased the timeout value from an extremely small interval to a reasonably small interval. I then measured the CPU usage statistics of the patched code in a scenario similar to the one described above and here is the result: $ pidstat -p 5287 1 100 Linux 3.3.6 (alan) 05/14/2012 _x86_64_ (4 CPU) 10:46:06 AM PID %usr %system %guest %CPU CPU Command 10:46:07 AM 5287 0.00 0.00 0.00 0.00 2 /usr/sbin/apt-c 10:46:08 AM 5287 0.00 0.00 0.00 0.00 2 /usr/sbin/apt-c 10:46:09 AM 5287 0.00 0.00 0.00 0.00 2 /usr/sbin/apt-c 10:46:10 AM 5287 0.00 0.00 0.00 0.00 2 /usr/sbin/apt-c ... [cut many similar lines] ... 10:47:43 AM 5287 0.00 1.00 0.00 1.00 0 /usr/sbin/apt-c 10:47:44 AM 5287 0.00 0.00 0.00 0.00 0 /usr/sbin/apt-c 10:47:45 AM 5287 0.00 0.00 0.00 0.00 0 /usr/sbin/apt-c 10:47:46 AM 5287 0.00 0.00 0.00 0.00 0 /usr/sbin/apt-c Average: 5287 0.07 0.04 0.00 0.11 - /usr/sbin/apt-c This is what I would consider a normal average value for a lightweight IO-bound process on this CPU class. I still don't know if modifying the timeout value as I did can have other unwanted consequences but maybe it is a good starting point for further debugging. Best regards.
--- End Message ---
--- Begin Message ---Source: apt-cacher Source-Version: 1.7.5 We believe that the bug you reported is fixed in the latest version of apt-cacher, which is due to be installed in the Debian FTP archive. A summary of the changes between this version and the previous one is attached. Thank you for reporting the bug, which will now be closed. If you have further comments please address them to [email protected], and the maintainer will reopen the bug report if appropriate. Debian distribution maintenance software pp. Mark Hindley <[email protected]> (supplier of updated apt-cacher package) (This message was generated automatically at their request; if you believe that there is a problem with it please contact the archive administrators by mailing [email protected]) -----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 Format: 1.8 Date: Mon, 20 Aug 2012 08:26:37 +0100 Source: apt-cacher Binary: apt-cacher Architecture: source all Version: 1.7.5 Distribution: unstable Urgency: low Maintainer: Mark Hindley <[email protected]> Changed-By: Mark Hindley <[email protected]> Description: apt-cacher - Caching proxy for Debian package and source files Closes: 672871 682437 685051 Changes: apt-cacher (1.7.5) unstable; urgency=low . * Fix receiving with Transfer-Encoding: chunked (closes: #682437, #685051). * When fetching, if checksum for index file fails, retry after refreshing Release file. * Don't abuse internal request headers by using X-AptCacher-Internal. * Handle failure of print in fetcher gracefully. * Implement curl_throttle to control libcurl CPU usage (closes: #672871). * Add configuration option skip_checksum_files_regexp. * Protect against empty Connection header in response. * When doing case insensitive comparison use faster lc() rather than regexp. Checksums-Sha1: 24deedd2eb566cdc8d0147c0dbde7322a314a7e4 857 apt-cacher_1.7.5.dsc 70af271da3507981c66662227f16eb6201801994 105320 apt-cacher_1.7.5.tar.gz 91ee6ec020deacd68e5c45ef303c160aeeaca133 103604 apt-cacher_1.7.5_all.deb Checksums-Sha256: c5ecd4ab8faf4780cad79299e417a4fafe236dcf63d85bee61443e1446b09d7d 857 apt-cacher_1.7.5.dsc 1c9f715b3ffb4781923d3f705d40dde302062fae921846cf2d6d8409d3d4a3e0 105320 apt-cacher_1.7.5.tar.gz e6d7047a054b720cff4b5205e107f0dbf8a4c93d120ecadeec26aa84b4cf3777 103604 apt-cacher_1.7.5_all.deb Files: bf311b05cb42f58185db3c8d89c3e6ff 857 net optional apt-cacher_1.7.5.dsc 2e78c2e2391065bdd93dce868348ba3e 105320 net optional apt-cacher_1.7.5.tar.gz e3ea03132b10b4188a6e3a96d271d5c9 103604 net optional apt-cacher_1.7.5_all.deb -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.12 (GNU/Linux) iD8DBQFQYgd/4QZIHu3wCMURAisiAJ9/DMY91g8dXpB3G6iezOd63YmeNQCfWVyG m14migFounkPhhxf+fwACKE= =JyPl -----END PGP SIGNATURE-----
--- End Message ---
