[Piuparts-devel] piuparts-report timings

Fri Feb 22 08:58:30 UTC 2013

On 2013-02-22 01:39, Dave Steele wrote:
>> Watching the messages scroll by, "writing package templates" doesn't
>> even look like the heavy hitter - successfully-tested feels like it
>> takes longer (the log entries need to have seconds resolution)

well, for sid that's 30 MB (state-successfully-tested.html) + 6 MB (pass.html)

$ du -skh /org/piuparts.debian.org/htdocs/sid/main/source
342M    /org/piuparts.debian.org/htdocs/sid/main/source

but writing these 340 MB can't "disappear" somehow ...

seconds-resolution times sid: see below

>> Your detect_well_known_errors run is maybe faster than I expected.
>> Your piuparts-report run seems way slow.

/usr/bin/time piuparts report

before rpy fix with 62 plots:
582.39user 534.54system 2:23:05elapsed 13%CPU (0avgtext+0avgdata 5667956maxresident)k
390024inputs+18548560outputs (231major+13396636minor)pagefaults 0swaps

with rpy fix and 86 plots:
601.78user 609.77system 2:15:04elapsed 14%CPU (0avgtext+0avgdata 5665480maxresident)k
240280inputs+18550120outputs (191major+13623045minor)pagefaults 0swaps

no change to memory consumption

>> Could it be available buffer space?

Intel(R) Xeon(R) CPU E31235 @ 3.20GHz, 16 GB RAM, wheezy/amd64 (+ stable + sid mix), kernel 3.7 from experimental, xfs on SAMSUNG HD103UJ 1TB hdd, no LVM

with eatmydata on a fully loaded system (8 slaves running):

08:16 source: 18358
08:16 Writing package templates in sid/main
08:19 Writing maintainer summaries in /org/piuparts.debian.org/htdocs/sid/main
08:19 Writing section index page

so (not) syncing makes a difference

>> top - 19:12:31 up 16 days,  8:25,  6 users,  load average: 0.65, 0.78, 0.51
>> Tasks: 229 total,   3 running, 225 sleeping,   0 stopped,   1 zombie
>> %Cpu(s): 16.4 us,  3.8 sy,  0.0 ni, 77.9 id,  1.7 wa,  0.0 hi,  0.2 si,  0.0 st
>> KiB Mem:  10236532 total,  9265276 used,   971256 free,   640960 buffers
>> KiB Swap: 20903932 total,   153916 used, 20750016 free,  5019796 cached
>>
>>   PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM     TIME+ COMMAND
>> 26835 piupart+  20   0  675m 552m 7660 R  98.1  5.5   0:22.16 piuparts-report
>>  3410 root      20   0  325m 115m 8264 S   3.3  1.2 153:30.72 Xorg

top - 08:24:28 up 10 days, 21:15, 26 users,  load average: 8.83, 8.60, 8.18
Tasks: 274 total,  12 running, 262 sleeping,   0 stopped,   0 zombie
%Cpu(s): 13.0 us,  7.5 sy, 73.9 ni,  5.4 id,  0.0 wa,  0.0 hi,  0.2 si,  0.0 st
KiB Mem:  16411480 total, 15179384 used,  1232096 free,    87236 buffers
KiB Swap: 31246420 total,  2206420 used, 29040000 free,  6413828 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND
 3994 piuparts  20   0 1110m 975m 8256 R 101.3  6.1   2:53.14 /usr/bin/python /org/piuparts.debian.org/share/piuparts/piuparts-report

thats running section #3, memory usage will grow over time

slaves stopped and with cold caches and eatmydata:

08:40:30 Running section sid/main
08:40:30 Loading and parsing Packages file
08:40:34 Fetching http://debian.local/debian/dists/sid/main/source/Sources.bz2
08:40:36 Finding log files
08:40:36 Archiving logs of obsolete packages
08:40:36 Copying log files
08:40:37 Removing old log files
08:40:37 Writing per-dir HTML pages
08:40:37 Writing counts.txt
08:40:37 successfully-tested: 38206
08:40:37 failed-testing: 74
08:40:37 cannot-be-tested: 1
08:40:37 essential-required: 61
08:40:37 waiting-to-be-tested: 0
08:40:37 waiting-for-dependency-to-be-tested: 0
08:40:37 dependency-failed-testing: 23
08:40:37 dependency-cannot-be-tested: 32
08:40:37 dependency-does-not-exist: 79
08:40:37 circular-dependency: 0
08:40:37 unknown: 0
08:40:37 unknown-preferred-alternative: 0
08:40:37 outdated: 0
08:40:37 total: 38476
08:40:37 source: 18358
08:40:37 Writing package templates in sid/main
08:44:20 Writing maintainer summaries in /org/piuparts.debian.org/htdocs/sid/main
08:44:51 Writing section index page
08:44:51 analysis template initdscript_lsb_header_issue.tpl does not exist.
...
08:44:51 analysis template unknown_failures.tpl does not exist.
08:44:51 Writing stats pages for sid/main
08:44:51 Writing page for successfully-tested
08:44:57 Writing page for failed-testing
08:44:57 Writing page for cannot-be-tested
08:44:57 Writing page for essential-required
08:44:57 Writing page for waiting-to-be-tested
08:44:57 Writing page for waiting-for-dependency-to-be-tested
08:44:57 Writing page for dependency-failed-testing
08:44:57 Writing page for dependency-cannot-be-tested
08:44:57 Writing page for dependency-does-not-exist
08:44:57 Writing page for unknown
08:44:57 Writing page for outdated
08:44:57 -------------------------------------------

slaves stopped, hot caches, eatmydata:

08:50:17 Running section sid/main
08:50:17 Loading and parsing Packages file
08:50:22 Fetching http://debian.local/debian/dists/sid/main/source/Sources.bz2
08:50:24 Finding log files
08:50:24 Archiving logs of obsolete packages
08:50:24 Copying log files
08:50:24 Removing old log files
08:50:24 Writing per-dir HTML pages
08:50:25 Writing counts.txt
08:50:25 successfully-tested: 38206
08:50:25 failed-testing: 74
08:50:25 cannot-be-tested: 1
08:50:25 essential-required: 61
08:50:25 waiting-to-be-tested: 0
08:50:25 waiting-for-dependency-to-be-tested: 0
08:50:25 dependency-failed-testing: 23
08:50:25 dependency-cannot-be-tested: 32
08:50:25 dependency-does-not-exist: 79
08:50:25 circular-dependency: 0
08:50:25 unknown: 0
08:50:25 unknown-preferred-alternative: 0
08:50:25 outdated: 0
08:50:25 total: 38476
08:50:25 source: 18358
08:50:25 Writing package templates in sid/main
08:54:04 Writing maintainer summaries in /org/piuparts.debian.org/htdocs/sid/main
08:54:42 Writing section index page
08:54:42 analysis template initdscript_lsb_header_issue.tpl does not exist.
...
08:54:42 analysis template unknown_failures.tpl does not exist.
08:54:42 Writing stats pages for sid/main
08:54:42 Writing page for successfully-tested
08:54:48 Writing page for failed-testing
08:54:48 Writing page for cannot-be-tested
08:54:48 Writing page for essential-required
08:54:48 Writing page for waiting-to-be-tested
08:54:48 Writing page for waiting-for-dependency-to-be-tested
08:54:48 Writing page for dependency-failed-testing
08:54:48 Writing page for dependency-cannot-be-tested
08:54:49 Writing page for dependency-does-not-exist
08:54:49 Writing page for unknown
08:54:49 Writing page for outdated
08:54:49 -------------------------------------------

So let's do only sid and put the output on tmpfs
There are 2.2G of logfiles in /org/piuparts.debian.org/master/sid/main/pass/
initial copying takes some time, but they can be fully cached in memory :-)

08:55:52 Running section sid/main
08:55:52 Loading and parsing Packages file
08:55:52 Fetching http://debian.local/debian/dists/sid/main/binary-amd64/Packages.bz2
08:55:59 Fetching http://debian.local/debian/dists/sid/main/source/Sources.bz2
08:56:01 Finding log files
08:56:01 Archiving logs of obsolete packages
08:56:01 Copying log files
09:01:23 Removing old log files
09:01:23 Writing per-dir HTML pages
09:01:24 Writing counts.txt
09:01:24 successfully-tested: 38206
09:01:24 failed-testing: 74
09:01:24 cannot-be-tested: 1
09:01:24 essential-required: 61
09:01:24 waiting-to-be-tested: 0
09:01:24 waiting-for-dependency-to-be-tested: 0
09:01:24 dependency-failed-testing: 23
09:01:24 dependency-cannot-be-tested: 32
09:01:24 dependency-does-not-exist: 79
09:01:24 circular-dependency: 0
09:01:24 unknown: 0
09:01:24 unknown-preferred-alternative: 0
09:01:24 outdated: 0
09:01:24 total: 38476
09:01:24 source: 18358
09:01:24 writing new file: /tmp/piuparts-htdocs/sid/main/counts.txt
09:01:24 appending line: 20130222, 38206, 74, 1, 61, 0, 0, 23, 32, 79, 0, 0, 0, 0
09:01:24 Writing package templates in sid/main
09:01:28 Writing maintainer summaries in /tmp/piuparts-htdocs/sid/main
09:01:28 Writing section index page
09:01:28 analysis template initdscript_lsb_header_issue.tpl does not exist.
...
09:01:28 analysis template unknown_failures.tpl does not exist.
09:01:29 Writing stats pages for sid/main
09:01:29 Writing page for successfully-tested
09:01:35 Writing page for failed-testing
09:01:35 Writing page for cannot-be-tested
09:01:35 Writing page for essential-required
09:01:35 Writing page for waiting-to-be-tested
09:01:35 Writing page for waiting-for-dependency-to-be-tested
09:01:35 Writing page for dependency-failed-testing
09:01:35 Writing page for dependency-cannot-be-tested
09:01:35 Writing page for dependency-does-not-exist
09:01:35 Writing page for unknown
09:01:35 Writing page for outdated
09:01:35 Writing static pages
Traceback (most recent call last):

and without need to copy:
09:09:21 Running section sid/main
09:09:21 Loading and parsing Packages file
09:09:21 Fetching http://debian.local/debian/dists/sid/main/binary-amd64/Packages.bz2
09:09:29 Fetching http://debian.local/debian/dists/sid/main/source/Sources.bz2
09:09:31 Finding log files
09:09:31 Archiving logs of obsolete packages
09:09:31 Copying log files
09:09:31 Removing old log files
09:09:31 Writing per-dir HTML pages
09:09:32 Writing counts.txt
09:09:32 successfully-tested: 38206
09:09:32 failed-testing: 74
09:09:32 cannot-be-tested: 1
09:09:32 essential-required: 61
09:09:32 waiting-to-be-tested: 0
09:09:32 waiting-for-dependency-to-be-tested: 0
09:09:32 dependency-failed-testing: 23
09:09:32 dependency-cannot-be-tested: 32
09:09:32 dependency-does-not-exist: 79
09:09:32 circular-dependency: 0
09:09:32 unknown: 0
09:09:32 unknown-preferred-alternative: 0
09:09:32 outdated: 0
09:09:32 total: 38476
09:09:32 source: 18358
09:09:32 Writing package templates in sid/main
09:09:36 Writing maintainer summaries in /tmp/piuparts-htdocs/sid/main
09:09:36 Writing section index page
09:09:36 analysis template initdscript_lsb_header_issue.tpl does not exist.
...
09:09:36 analysis template unknown_failures.tpl does not exist.
09:09:37 Writing stats pages for sid/main
09:09:37 Writing page for successfully-tested
09:09:43 Writing page for failed-testing
09:09:43 Writing page for cannot-be-tested
09:09:43 Writing page for essential-required
09:09:43 Writing page for waiting-to-be-tested
09:09:43 Writing page for waiting-for-dependency-to-be-tested
09:09:43 Writing page for dependency-failed-testing
09:09:43 Writing page for dependency-cannot-be-tested
09:09:43 Writing page for dependency-does-not-exist
09:09:43 Writing page for unknown
09:09:43 Writing page for outdated
09:09:43 Writing static pages
Traceback (most recent call last):

and dropping eatmydata does not make a difference here ...

but it clearly shows that that's an I/O problem, not a algorithmic one.

Btw, the navigation bar for 86 sections takes 8-10 KB per file, and
for most source summaries, that's > 50% file size

so back to the normal file system, eatmydata, but only 2 out of 86
sections:

09:50:54 source: 18358
09:50:54 Writing source summaries in sid/main
09:52:40 Writing 3100 maintainer summaries in /org/piuparts.debian.org/htdocs/sid/main
09:53:01 Writing section index page

so total write size matters: that was only 150 MB vs. 342 MB previously.

Andreas