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/60.runsolver.aptitude aptitude -s -y --without-recommends install eximon kid3 libwine-capi cpipe grcm 

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

[startup+0 s]
/proc/loadavg: 1.00 1.04 1.03 2/55 25752
/proc/meminfo: memFree=829816/1022884 swapFree=0/0
[pid=25752] ppid=25751 vsize=3152 CPUtime=0
/proc/25752/stat : 25752 (runsolver) R 25751 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29610752 3227648 32 18446744073709551615 134512640 134586868 4290431376 4290429424 4152165424 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25752/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.128003 s]
/proc/loadavg: 1.00 1.04 1.03 2/55 25752
/proc/meminfo: memFree=829816/1022884 swapFree=0/0
[pid=25752] ppid=25751 vsize=103288 CPUtime=0.11
/proc/25752/stat : 25752 (aptitude) R 25751 25752 17863 34816 17863 4202496 11224 1708 0 0 10 1 0 0 20 0 1 0 29610752 105766912 11026 18446744073709551615 140306767683584 140306771990936 140736780447168 140736780438432 140306762528517 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25752/statm: 25822 11026 9813 1052 0 1159 0
Current children cumulated CPU time (s) 0.11
Current children cumulated vsize (KiB) 103288

[startup+0.200284 s]
/proc/loadavg: 1.00 1.04 1.03 2/55 25752
/proc/meminfo: memFree=829816/1022884 swapFree=0/0
[pid=25752] ppid=25751 vsize=103288 CPUtime=0.19
/proc/25752/stat : 25752 (aptitude) R 25751 25752 17863 34816 17863 4202496 11300 1708 0 0 18 1 0 0 20 0 1 0 29610752 105766912 11102 18446744073709551615 140306767683584 140306771990936 140736780447168 140736780438432 140306762525166 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25752/statm: 25822 11102 9889 1052 0 1159 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 103288

[startup+0.300267 s]
/proc/loadavg: 1.00 1.04 1.03 2/55 25752
/proc/meminfo: memFree=829816/1022884 swapFree=0/0
[pid=25752] ppid=25751 vsize=103432 CPUtime=0.29
/proc/25752/stat : 25752 (aptitude) R 25751 25752 17863 34816 17863 4202496 11427 1708 0 0 28 1 0 0 20 0 1 0 29610752 105914368 11221 18446744073709551615 140306767683584 140306771990936 140736780447168 140736780436944 140306762536930 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25752/statm: 25858 11221 9956 1052 0 1195 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 103432

[startup+0.700199 s]
/proc/loadavg: 1.00 1.04 1.03 2/55 25752
/proc/meminfo: memFree=829816/1022884 swapFree=0/0
[pid=25752] ppid=25751 vsize=123068 CPUtime=0.68
/proc/25752/stat : 25752 (aptitude) R 25751 25752 17863 34816 17863 4202496 17688 1708 0 0 64 4 0 0 20 0 1 0 29610752 126021632 15966 18446744073709551615 140306767683584 140306771990936 140736780447168 140736780436600 140306762583859 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25752/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.00 1.04 1.03 2/57 25757
/proc/meminfo: memFree=809844/1022884 swapFree=0/0
[pid=25752] ppid=25751 vsize=136044 CPUtime=1.48
/proc/25752/stat : 25752 (aptitude) R 25751 25752 17863 34816 17863 4202496 20639 1708 0 0 142 6 0 0 20 0 2 0 29610752 139309056 17558 18446744073709551615 140306767683584 140306771990936 140736780447168 140736780438440 140306769885203 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25752/statm: 34011 17558 10207 1052 0 9348 0
[pid=25752/tid=25757] ppid=25751 vsize=136044 CPUtime=0
/proc/25752/task/25757/stat : 25757 (aptitude) S 25751 25752 17863 34816 17863 4202560 4 1708 0 0 0 0 0 0 20 0 2 0 29610829 139309056 17558 18446744073709551615 140306767683584 140306771990936 140736780447168 140306655361024 140306736427732 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) 136044

[startup+3.10025 s]
/proc/loadavg: 1.00 1.04 1.03 2/57 25757
/proc/meminfo: memFree=799552/1022884 swapFree=0/0
[pid=25752] ppid=25751 vsize=137796 CPUtime=3.07
/proc/25752/stat : 25752 (aptitude) R 25751 25752 17863 34816 17863 4202496 21982 2206 0 0 297 10 0 0 20 0 2 0 29610752 141103104 17928 18446744073709551615 140306767683584 140306771990936 140736780447168 140736780433872 140306770678052 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25752/statm: 34449 17928 10303 1052 0 9786 0
[pid=25752/tid=25757] ppid=25751 vsize=137796 CPUtime=0
/proc/25752/task/25757/stat : 25757 (aptitude) S 25751 25752 17863 34816 17863 4202560 6 2206 0 0 0 0 0 0 20 0 2 0 29610829 141103104 17928 18446744073709551615 140306767683584 140306771990936 140736780447168 140306655361024 140306736427732 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) 137796

[startup+6.30025 s]
/proc/loadavg: 1.00 1.04 1.03 2/57 25758
/proc/meminfo: memFree=757516/1022884 swapFree=0/0
[pid=25752] ppid=25751 vsize=251380 CPUtime=6.25
/proc/25752/stat : 25752 (aptitude) S 25751 25752 17863 34816 17863 4202496 35002 2206 0 0 612 13 0 0 20 0 2 0 29610752 257413120 30169 18446744073709551615 140306767683584 140306771990936 140736780447168 140736780438928 140306736428619 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25752/statm: 62845 30169 10359 1052 0 38182 0
[pid=25752/tid=25757] ppid=25751 vsize=251380 CPUtime=2.86
/proc/25752/task/25757/stat : 25757 (aptitude) R 25751 25752 17863 34816 17863 4202560 13019 2206 0 0 283 3 0 0 20 0 2 0 29610829 257413120 30169 18446744073709551615 140306767683584 140306771990936 140736780447168 140306655354680 140306770379621 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) 251380

[startup+12.7002 s]
/proc/loadavg: 1.00 1.04 1.03 2/57 25758
/proc/meminfo: memFree=704940/1022884 swapFree=0/0
[pid=25752] ppid=25751 vsize=302928 CPUtime=12.61
/proc/25752/stat : 25752 (aptitude) S 25751 25752 17863 34816 17863 4202496 48185 2206 0 0 1243 18 0 0 20 0 2 0 29610752 310198272 43059 18446744073709551615 140306767683584 140306771990936 140736780447168 140736780438928 140306736428619 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25752/statm: 75732 43059 10360 1052 0 51069 0
[pid=25752/tid=25757] ppid=25751 vsize=302928 CPUtime=9.22
/proc/25752/task/25757/stat : 25757 (aptitude) R 25751 25752 17863 34816 17863 4202560 26202 2206 0 0 914 8 0 0 20 0 2 0 29610829 310198272 43059 18446744073709551615 140306767683584 140306771990936 140736780447168 140306655352296 140306770308267 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 12.61
Current children cumulated vsize (KiB) 302928

[startup+25.5003 s]
/proc/loadavg: 1.00 1.04 1.03 2/57 25758
/proc/meminfo: memFree=611940/1022884 swapFree=0/0
[pid=25752] ppid=25751 vsize=390664 CPUtime=25.36
/proc/25752/stat : 25752 (aptitude) S 25751 25752 17863 34816 17863 4202496 70125 2206 0 0 2508 28 0 0 20 0 2 0 29610752 400039936 64965 18446744073709551615 140306767683584 140306771990936 140736780447168 140736780438928 140306736428619 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25752/statm: 97666 64965 10360 1052 0 73003 0
[pid=25752/tid=25757] ppid=25751 vsize=390664 CPUtime=21.96
/proc/25752/task/25757/stat : 25757 (aptitude) R 25751 25752 17863 34816 17863 4202560 48142 2206 0 0 2178 18 0 0 20 0 2 0 29610829 400039936 64965 18446744073709551615 140306767683584 140306771990936 140736780447168 140306655352344 140306725223915 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 25.36
Current children cumulated vsize (KiB) 390664

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

[startup+25.6004 s]
/proc/loadavg: 1.00 1.04 1.03 2/57 25758
/proc/meminfo: memFree=611940/1022884 swapFree=0/0
[pid=25752] ppid=25751 vsize=391324 CPUtime=25.45
/proc/25752/stat : 25752 (aptitude) S 25751 25752 17863 34816 17863 4202496 70281 2206 0 0 2517 28 0 0 20 0 2 0 29610752 400715776 65121 18446744073709551615 140306767683584 140306771990936 140736780447168 140736780438928 140306736428619 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25752/statm: 97831 65121 10360 1052 0 73168 0
[pid=25752/tid=25757] ppid=25751 vsize=391324 CPUtime=22.06
/proc/25752/task/25757/stat : 25757 (aptitude) R 25751 25752 17863 34816 17863 4202560 48298 2206 0 0 2188 18 0 0 20 0 2 0 29610829 400715776 65121 18446744073709551615 140306767683584 140306771990936 140736780447168 140306655352344 140306770353718 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 25.45
Current children cumulated vsize (KiB) 391324

[startup+27.2002 s]
/proc/loadavg: 1.00 1.04 1.03 2/57 25758
/proc/meminfo: memFree=604500/1022884 swapFree=0/0
[pid=25752] ppid=25751 vsize=402164 CPUtime=27.05
/proc/25752/stat : 25752 (aptitude) S 25751 25752 17863 34816 17863 4202496 72992 2206 0 0 2676 29 0 0 20 0 2 0 29610752 411815936 67832 18446744073709551615 140306767683584 140306771990936 140736780447168 140736780438928 140306736428619 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25752/statm: 100541 67832 10360 1052 0 75878 0
[pid=25752/tid=25757] ppid=25751 vsize=402164 CPUtime=23.65
/proc/25752/task/25757/stat : 25757 (aptitude) R 25751 25752 17863 34816 17863 4202560 51009 2206 0 0 2346 19 0 0 20 0 2 0 29610829 411815936 67832 18446744073709551615 140306767683584 140306771990936 140736780447168 140306655353952 140306770345100 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 27.05
Current children cumulated vsize (KiB) 402164

[startup+28.0003 s]
/proc/loadavg: 1.00 1.04 1.03 2/57 25758
/proc/meminfo: memFree=596936/1022884 swapFree=0/0
[pid=25752] ppid=25751 vsize=405468 CPUtime=27.84
/proc/25752/stat : 25752 (aptitude) R 25751 25752 17863 34816 17863 4202496 74023 2206 0 0 2755 29 0 0 20 0 2 0 29610752 415199232 68807 18446744073709551615 140306767683584 140306771990936 140736780447168 140736780437304 140306725174955 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25752/statm: 101367 68807 10408 1052 0 76697 0
[pid=25752/tid=25757] ppid=25751 vsize=405468 CPUtime=24.11
/proc/25752/task/25757/stat : 25757 (aptitude) S 25751 25752 17863 34816 17863 4202560 51806 2206 0 0 2391 20 0 0 20 0 2 0 29610829 415199232 68807 18446744073709551615 140306767683584 140306771990936 140736780447168 140306655361024 140306736427732 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 27.84
Current children cumulated vsize (KiB) 405468

[startup+28.4002 s]
/proc/loadavg: 1.00 1.04 1.03 2/57 25758
/proc/meminfo: memFree=596936/1022884 swapFree=0/0
[pid=25752] ppid=25751 vsize=405468 CPUtime=28.24
/proc/25752/stat : 25752 (aptitude) R 25751 25752 17863 34816 17863 4202496 76556 2206 0 0 2794 30 0 0 20 0 2 0 29610752 415199232 68776 18446744073709551615 140306767683584 140306771990936 140736780447168 140736780439368 140306769889959 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25752/statm: 101367 68776 10409 1052 0 76697 0
[pid=25752/tid=25757] ppid=25751 vsize=405468 CPUtime=24.11
/proc/25752/task/25757/stat : 25757 (aptitude) S 25751 25752 17863 34816 17863 4202560 51806 2206 0 0 2391 20 0 0 20 0 2 0 29610829 415199232 68776 18446744073709551615 140306767683584 140306771990936 140736780447168 140306655361024 140306736427732 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 28.24
Current children cumulated vsize (KiB) 405468

[startup+28.8008 s]
/proc/loadavg: 1.00 1.04 1.03 2/57 25759
/proc/meminfo: memFree=594572/1022884 swapFree=0/0
[pid=25752] ppid=25751 vsize=234524 CPUtime=28.63
/proc/25752/stat : 25752 (aptitude) R 25751 25752 17863 34816 17863 4202496 77372 2706 0 0 2818 44 0 1 20 0 1 0 29610752 240152576 22021 18446744073709551615 140306767683584 140306771990936 140736780447168 140736780444280 140306725564695 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25752/statm: 58631 22021 6316 1052 0 33961 0
Current children cumulated CPU time (s) 28.63
Current children cumulated vsize (KiB) 234524

Child status: 0
Real time (s): 28.8235
CPU time (s): 28.6778
CPU user time (s): 28.1978
CPU system time (s): 0.48003
CPU usage (%): 99.4945
Max. virtual memory (cumulated for all children) (KiB): 405468

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 28.1978
system time used= 0.48003
maximum resident set size= 276004
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 80185
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= 115
involuntary context switches= 530

runsolver used 0.036002 second user time and 0.100006 second system time

The end