runsolver Copyright (C) 2010 Olivier ROUSSEL

This is runsolver version 3.2.9a (svn: 651)

This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
GNU General Public License for more details.

command line: runsolver -W 300 -M 1124 -w /home/cbse/results/sarge-etch-lenny-squeeze-sid/logs/32.runsolver.aptitude aptitude -s -y --without-recommends install libotr1-bin archivemail cbmlink cccd libasound2-plugins 

Enforcing wall clock limit (soft limit, will send signal-name then SIGKILL): 300 seconds
Enforcing VSIZE limit (soft limit, will send signal-name then SIGKILL): 1150976 KiB
Enforcing VSIZE limit (hard limit, stack expansion will fail with SIGSEGV, brk() and mmap() will return ENOMEM): 1202176 KiB
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.05 1.07 1.03 2/55 25266
/proc/meminfo: memFree=833040/1022884 swapFree=0/0
[pid=25266] ppid=25265 vsize=54860 CPUtime=0
/proc/25266/stat : 25266 (aptitude) R 25265 25266 17863 34816 17863 4202496 579 0 0 0 0 0 0 0 20 0 1 0 29452533 56176640 479 18446744073709551615 139659777527808 139659781835160 140736138370512 140736138369720 139659775330182 0 0 0 0 0 0 0 17 0 0 0 0 0 0
/proc/25266/statm: 13715 479 390 1052 0 73 0

[startup+0.147068 s]
/proc/loadavg: 1.05 1.07 1.03 2/55 25266
/proc/meminfo: memFree=833040/1022884 swapFree=0/0
[pid=25266] ppid=25265 vsize=103288 CPUtime=0.12
/proc/25266/stat : 25266 (aptitude) R 25265 25266 17863 34816 17863 4202496 11273 1707 0 0 10 2 0 0 20 0 1 0 29452533 105766912 11075 18446744073709551615 139659777527808 139659781835160 140736138370512 140736138361776 139659772368701 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25266/statm: 25822 11075 9862 1052 0 1159 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 103288

[startup+0.200405 s]
/proc/loadavg: 1.05 1.07 1.03 2/55 25266
/proc/meminfo: memFree=833040/1022884 swapFree=0/0
[pid=25266] ppid=25265 vsize=103288 CPUtime=0.19
/proc/25266/stat : 25266 (aptitude) R 25265 25266 17863 34816 17863 4202496 11300 1707 0 0 16 3 0 0 20 0 1 0 29452533 105766912 11102 18446744073709551615 139659777527808 139659781835160 140736138370512 140736138361776 139659772368459 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25266/statm: 25822 11102 9889 1052 0 1159 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 103288

[startup+0.300272 s]
/proc/loadavg: 1.05 1.07 1.03 2/55 25266
/proc/meminfo: memFree=833040/1022884 swapFree=0/0
[pid=25266] ppid=25265 vsize=103432 CPUtime=0.28
/proc/25266/stat : 25266 (aptitude) R 25265 25266 17863 34816 17863 4202496 11427 1707 0 0 25 3 0 0 20 0 1 0 29452533 105914368 11221 18446744073709551615 139659777527808 139659781835160 140736138370512 140736138360288 139659772381154 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25266/statm: 25858 11221 9956 1052 0 1195 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 103432

[startup+0.700201 s]
/proc/loadavg: 1.05 1.07 1.03 2/55 25266
/proc/meminfo: memFree=833040/1022884 swapFree=0/0
[pid=25266] ppid=25265 vsize=123068 CPUtime=0.68
/proc/25266/stat : 25266 (aptitude) R 25265 25266 17863 34816 17863 4202496 17688 1707 0 0 61 7 0 0 20 0 1 0 29452533 126021632 15966 18446744073709551615 139659777527808 139659781835160 140736138370512 140736138359944 139659772428288 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25266/statm: 30767 15966 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123068

[startup+1.50024 s]
/proc/loadavg: 1.04 1.07 1.03 2/57 25271
/proc/meminfo: memFree=813068/1022884 swapFree=0/0
[pid=25266] ppid=25265 vsize=136040 CPUtime=1.48
/proc/25266/stat : 25266 (aptitude) R 25265 25266 17863 34816 17863 4202496 20639 1707 0 0 140 8 0 0 20 0 2 0 29452533 139304960 17558 18446744073709551615 139659777527808 139659781835160 140736138370512 140736138361784 139659779729452 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25266/statm: 34010 17558 10207 1052 0 9347 0
[pid=25266/tid=25271] ppid=25265 vsize=136040 CPUtime=0
/proc/25266/task/25271/stat : 25271 (aptitude) S 25265 25266 17863 34816 17863 4202560 4 1707 0 0 0 0 0 0 20 0 2 0 29452610 139304960 17558 18446744073709551615 139659777527808 139659781835160 140736138370512 139659665205248 139659746271956 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 136040

[startup+3.10024 s]
/proc/loadavg: 1.04 1.07 1.03 2/57 25271
/proc/meminfo: memFree=802776/1022884 swapFree=0/0
[pid=25266] ppid=25265 vsize=137792 CPUtime=3.07
/proc/25266/stat : 25266 (aptitude) R 25265 25266 17863 34816 17863 4202496 21977 2205 0 0 293 13 1 0 20 0 2 0 29452533 141099008 17922 18446744073709551615 139659777527808 139659781835160 140736138370512 140736138357216 139659735038279 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/25266/statm: 34448 17922 10303 1052 0 9785 0
[pid=25266/tid=25271] ppid=25265 vsize=137792 CPUtime=0.01
/proc/25266/task/25271/stat : 25271 (aptitude) S 25265 25266 17863 34816 17863 4202560 6 2205 0 0 0 0 1 0 20 0 2 0 29452610 141099008 17922 18446744073709551615 139659777527808 139659781835160 140736138370512 139659665205248 139659746271956 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 137792

[startup+6.30024 s]
/proc/loadavg: 1.04 1.07 1.03 2/57 25272
/proc/meminfo: memFree=760740/1022884 swapFree=0/0
[pid=25266] ppid=25265 vsize=186136 CPUtime=6.25
/proc/25266/stat : 25266 (aptitude) S 25265 25266 17863 34816 17863 4202496 34839 2205 0 0 606 18 1 0 20 0 2 0 29452533 190603264 30246 18446744073709551615 139659777527808 139659781835160 140736138370512 140736138362272 139659746272843 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/25266/statm: 46534 30246 10359 1052 0 21871 0
[pid=25266/tid=25271] ppid=25265 vsize=186136 CPUtime=2.87
/proc/25266/task/25271/stat : 25271 (aptitude) R 25265 25266 17863 34816 17863 4202560 12862 2205 0 0 282 4 1 0 20 0 2 0 29452610 190603264 30246 18446744073709551615 139659777527808 139659781835160 140736138370512 139659665196568 139659780263571 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 186136

[startup+12.7002 s]
/proc/loadavg: 1.04 1.07 1.03 2/57 25272
/proc/meminfo: memFree=712380/1022884 swapFree=0/0
[pid=25266] ppid=25265 vsize=297352 CPUtime=12.62
/proc/25266/stat : 25266 (aptitude) S 25265 25266 17863 34816 17863 4202496 46651 2205 0 0 1236 25 1 0 20 0 2 0 29452533 304488448 41653 18446744073709551615 139659777527808 139659781835160 140736138370512 140736138362272 139659746272843 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/25266/statm: 74338 41653 10360 1052 0 49675 0
[pid=25266/tid=25271] ppid=25265 vsize=297352 CPUtime=9.25
/proc/25266/task/25271/stat : 25271 (aptitude) R 25265 25266 17863 34816 17863 4202560 24673 2205 0 0 912 12 1 0 20 0 2 0 29452610 304488448 41653 18446744073709551615 139659777527808 139659781835160 140736138370512 139659665198176 139659735038279 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.62
Current children cumulated vsize (KiB) 297352

Solver just ended. Dumping a history of the last processes samples

[startup+12.8003 s]
/proc/loadavg: 1.04 1.07 1.03 2/57 25272
/proc/meminfo: memFree=712380/1022884 swapFree=0/0
[pid=25266] ppid=25265 vsize=298012 CPUtime=12.72
/proc/25266/stat : 25266 (aptitude) S 25265 25266 17863 34816 17863 4202496 46807 2205 0 0 1246 25 1 0 20 0 2 0 29452533 305164288 41809 18446744073709551615 139659777527808 139659781835160 140736138370512 140736138362272 139659746272843 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/25266/statm: 74503 41809 10360 1052 0 49840 0
[pid=25266/tid=25271] ppid=25265 vsize=298012 CPUtime=9.35
/proc/25266/task/25271/stat : 25271 (aptitude) R 25265 25266 17863 34816 17863 4202560 24829 2205 0 0 922 12 1 0 20 0 2 0 29452610 305164288 41809 18446744073709551615 139659777527808 139659781835160 140736138370512 139659665196616 139659735028388 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.72
Current children cumulated vsize (KiB) 298012

[startup+19.2002 s]
/proc/loadavg: 1.03 1.06 1.03 2/57 25272
/proc/meminfo: memFree=668608/1022884 swapFree=0/0
[pid=25266] ppid=25265 vsize=338012 CPUtime=19.09
/proc/25266/stat : 25266 (aptitude) S 25265 25266 17863 34816 17863 4202496 56858 2205 0 0 1880 28 1 0 20 0 2 0 29452533 346124288 51838 18446744073709551615 139659777527808 139659781835160 140736138370512 140736138362272 139659746272843 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/25266/statm: 84503 51838 10360 1052 0 59840 0
[pid=25266/tid=25271] ppid=25265 vsize=338012 CPUtime=15.71
/proc/25266/task/25271/stat : 25271 (aptitude) R 25265 25266 17863 34816 17863 4202560 34880 2205 0 0 1556 14 1 0 20 0 2 0 29452610 346124288 51838 18446744073709551615 139659777527808 139659781835160 140736138370512 139659665196568 139659778356784 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 19.09
Current children cumulated vsize (KiB) 338012

[startup+20.8002 s]
/proc/loadavg: 1.03 1.06 1.03 2/57 25272
/proc/meminfo: memFree=663772/1022884 swapFree=0/0
[pid=25266] ppid=25265 vsize=347544 CPUtime=20.68
/proc/25266/stat : 25266 (aptitude) S 25265 25266 17863 34816 17863 4202496 59249 2205 0 0 2039 28 1 0 20 0 2 0 29452533 355885056 54207 18446744073709551615 139659777527808 139659781835160 140736138370512 140736138362272 139659746272843 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/25266/statm: 86886 54207 10360 1052 0 62223 0
[pid=25266/tid=25271] ppid=25265 vsize=347544 CPUtime=17.31
/proc/25266/task/25271/stat : 25271 (aptitude) R 25265 25266 17863 34816 17863 4202560 37271 2205 0 0 1715 15 1 0 20 0 2 0 29452610 355885056 54207 18446744073709551615 139659777527808 139659781835160 140736138370512 139659665198776 139659743435808 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 20.68
Current children cumulated vsize (KiB) 347544

[startup+22.4002 s]
/proc/loadavg: 1.03 1.06 1.03 2/57 25272
/proc/meminfo: memFree=651124/1022884 swapFree=0/0
[pid=25266] ppid=25265 vsize=354592 CPUtime=22.28
/proc/25266/stat : 25266 (aptitude) S 25265 25266 17863 34816 17863 4202496 61013 2205 0 0 2198 29 1 0 20 0 2 0 29452533 363102208 55971 18446744073709551615 139659777527808 139659781835160 140736138370512 140736138362272 139659746272843 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/25266/statm: 88648 55971 10360 1052 0 63985 0
[pid=25266/tid=25271] ppid=25265 vsize=354592 CPUtime=18.91
/proc/25266/task/25271/stat : 25271 (aptitude) R 25265 25266 17863 34816 17863 4202560 39035 2205 0 0 1874 16 1 0 20 0 2 0 29452610 363102208 55971 18446744073709551615 139659777527808 139659781835160 140736138370512 139659665196568 139659780329775 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.28
Current children cumulated vsize (KiB) 354592

[startup+23.2073 s]
/proc/loadavg: 1.03 1.06 1.03 2/57 25272
/proc/meminfo: memFree=647900/1022884 swapFree=0/0
[pid=25266] ppid=25265 vsize=355976 CPUtime=23.08
/proc/25266/stat : 25266 (aptitude) R 25265 25266 17863 34816 17863 4202496 62278 2205 0 0 2277 30 1 0 20 0 2 0 29452533 364519424 56475 18446744073709551615 139659777527808 139659781835160 140736138370512 140736138360600 139659772352000 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/25266/statm: 88994 56475 10409 1052 0 64324 0
[pid=25266/tid=25271] ppid=25265 vsize=355976 CPUtime=19.25
/proc/25266/task/25271/stat : 25271 (aptitude) S 25265 25266 17863 34816 17863 4202560 39361 2205 0 0 1908 16 1 0 20 0 2 0 29452610 364519424 56475 18446744073709551615 139659777527808 139659781835160 140736138370512 139659665205248 139659746271956 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.08
Current children cumulated vsize (KiB) 355976

[startup+23.6002 s]
/proc/loadavg: 1.03 1.06 1.03 2/57 25272
/proc/meminfo: memFree=647900/1022884 swapFree=0/0
[pid=25266] ppid=25265 vsize=355976 CPUtime=23.46
/proc/25266/stat : 25266 (aptitude) R 25265 25266 17863 34816 17863 4202496 64454 2704 0 0 2309 36 1 0 20 0 2 0 29452533 364519424 56636 18446744073709551615 139659777527808 139659781835160 140736138370512 140736138361224 139659772649749 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/25266/statm: 88994 56636 10409 1052 0 64324 0
[pid=25266/tid=25271] ppid=25265 vsize=355976 CPUtime=19.25
/proc/25266/task/25271/stat : 25271 (aptitude) S 25265 25266 17863 34816 17863 4202560 39361 2704 0 0 1908 16 1 0 20 0 2 0 29452610 364519424 56636 18446744073709551615 139659777527808 139659781835160 140736138370512 139659665205248 139659746271956 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.46
Current children cumulated vsize (KiB) 355976

[startup+23.7007 s]
/proc/loadavg: 1.03 1.06 1.03 2/57 25272
/proc/meminfo: memFree=647900/1022884 swapFree=0/0
[pid=25266] ppid=25265 vsize=234444 CPUtime=23.56
/proc/25266/stat : 25266 (aptitude) R 25265 25266 17863 34816 17863 4202496 64905 2704 0 0 2313 42 1 0 20 0 1 0 29452533 240070656 25300 18446744073709551615 139659777527808 139659781835160 140736138370512 140736138367624 139659735408919 0 134217728 4096 0 0 0 0 17 0 0 0 1 0 0
/proc/25266/statm: 58611 25300 9388 1052 0 33941 0
Current children cumulated CPU time (s) 23.56
Current children cumulated vsize (KiB) 234444

Child status: 0
Real time (s): 23.7259
CPU time (s): 23.6095
CPU user time (s): 23.1534
CPU system time (s): 0.456028
CPU usage (%): 99.5094
Max. virtual memory (cumulated for all children) (KiB): 355976

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 23.1534
system time used= 0.456028
maximum resident set size= 226668
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 67717
page faults= 0
swaps= 0
block input operations= 0
block output operations= 144
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 106
involuntary context switches= 456

runsolver used 0.044002 second user time and 0.068004 second system time

The end