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/16.runsolver.aptitude aptitude -s -y --without-recommends install ipcheck wmcpu ndiswrapper-modules-2.6.8-4-686 suikyo-table nms-guestbook 

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.22 1.12 1.04 2/55 25113
/proc/meminfo: memFree=961588/1022884 swapFree=0/0
[pid=25113] ppid=25112 vsize=3152 CPUtime=0
/proc/25113/stat : 25113 (runsolver) R 25112 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29349779 3227648 32 18446744073709551615 134512640 134586868 4286632464 4286630512 4151354416 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25113/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.113351 s]
/proc/loadavg: 1.22 1.12 1.04 2/55 25113
/proc/meminfo: memFree=961588/1022884 swapFree=0/0
[pid=25113] ppid=25112 vsize=19848 CPUtime=0
/proc/25113/stat : 25113 (aptitude) D 25112 25113 17863 34816 17863 4202496 141 0 8 0 0 0 0 0 20 0 1 0 29349779 20324352 64 18446744073709551615 140439067705344 140439072012696 140736106837408 140736106834216 140439065563856 0 0 0 0 0 0 0 17 0 0 0 10 0 0
/proc/25113/statm: 4962 64 43 1052 0 31 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 19848

[startup+0.200418 s]
/proc/loadavg: 1.22 1.12 1.04 2/55 25113
/proc/meminfo: memFree=961588/1022884 swapFree=0/0
[pid=25113] ppid=25112 vsize=38696 CPUtime=0
/proc/25113/stat : 25113 (aptitude) D 25112 25113 17863 34816 17863 4202496 173 0 15 0 0 0 0 0 20 0 1 0 29349779 39624704 97 18446744073709551615 140439067705344 140439072012696 140736106837408 140736106833736 140439065563894 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/25113/statm: 9674 97 61 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 38696

[startup+0.300398 s]
/proc/loadavg: 1.22 1.12 1.04 2/55 25113
/proc/meminfo: memFree=961588/1022884 swapFree=0/0
[pid=25113] ppid=25112 vsize=54968 CPUtime=0
/proc/25113/stat : 25113 (aptitude) D 25112 25113 17863 34816 17863 4202496 1071 0 25 0 0 0 0 0 20 0 1 0 29349779 56287232 987 18446744073709551615 140439067705344 140439072012696 140736106837408 140736106833504 140439025393509 0 134217728 4096 0 0 0 0 17 0 0 0 27 0 0
/proc/25113/statm: 13742 987 824 1052 0 106 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54968

[startup+0.700301 s]
/proc/loadavg: 1.22 1.12 1.04 2/55 25113
/proc/meminfo: memFree=961588/1022884 swapFree=0/0
[pid=25113] ppid=25112 vsize=103288 CPUtime=0.02
/proc/25113/stat : 25113 (aptitude) D 25112 25113 17863 34816 17863 4202496 2634 1705 65 4 0 2 0 0 20 0 1 0 29349779 105766912 2499 18446744073709551615 140439067705344 140439072012696 140736106837408 140736106828880 140439062755226 0 134217728 4096 0 0 0 0 17 0 0 0 63 0 0
/proc/25113/statm: 25822 2499 1287 1052 0 1159 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 103288

[startup+1.5003 s]
/proc/loadavg: 1.22 1.12 1.04 1/56 25117
/proc/meminfo: memFree=952528/1022884 swapFree=0/0
[pid=25113] ppid=25112 vsize=103288 CPUtime=0.02
/proc/25113/stat : 25113 (aptitude) D 25112 25113 17863 34816 17863 4202496 4347 1705 194 4 0 2 0 0 20 0 1 0 29349779 105766912 4341 18446744073709551615 140439067705344 140439072012696 140736106837408 140736106828880 140439062755226 0 134217728 4096 0 0 0 0 17 0 0 0 142 0 0
/proc/25113/statm: 25822 4341 3129 1052 0 1159 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 103288

[startup+3.10031 s]
/proc/loadavg: 1.20 1.11 1.04 2/56 25117
/proc/meminfo: memFree=949924/1022884 swapFree=0/0
[pid=25113] ppid=25112 vsize=123068 CPUtime=0.54
/proc/25113/stat : 25113 (aptitude) D 25112 25113 17863 34816 17863 4202496 17354 1705 321 4 47 7 0 0 20 0 1 0 29349779 126021632 15951 18446744073709551615 140439067705344 140439072012696 140736106837408 140736106826840 140439036461424 0 134217728 4096 0 0 0 0 17 0 0 0 251 0 0
/proc/25113/statm: 30767 15951 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.54
Current children cumulated vsize (KiB) 123068
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.20 1.11 1.04 2/57 25119
/proc/meminfo: memFree=804952/1022884 swapFree=0/0
[pid=25113] ppid=25112 vsize=139664 CPUtime=3.06
/proc/25113/stat : 25113 (aptitude) S 25112 25113 17863 34816 17863 4202496 22865 2201 321 6 288 17 0 1 20 0 2 0 29349779 143015936 18615 18446744073709551615 140439067705344 140439072012696 140736106837408 140736106829168 140439036450379 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 314 0 0
/proc/25113/statm: 34916 18615 10350 1052 0 10253 0
[pid=25113/tid=25118] ppid=25112 vsize=139664 CPUtime=0.11
/proc/25113/task/25118/stat : 25118 (aptitude) R 25112 25113 17863 34816 17863 4202560 1462 2201 0 6 10 0 0 1 20 0 2 0 29350179 143015936 18615 18446744073709551615 140439067705344 140439072012696 140736106837408 140438955376920 140439034019801 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 139664
heavy processes:

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

[startup+6.40335 s]
/proc/loadavg: 1.20 1.11 1.04 2/57 25119
/proc/meminfo: memFree=801984/1022884 swapFree=0/0
[pid=25113] ppid=25112 vsize=144680 CPUtime=3.15
/proc/25113/stat : 25113 (aptitude) S 25112 25113 17863 34816 17863 4202496 24228 2201 321 6 297 17 0 1 20 0 2 0 29349779 148152320 19895 18446744073709551615 140439067705344 140439072012696 140736106837408 140736106829168 140439036450379 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 314 0 0
/proc/25113/statm: 36170 19895 10350 1052 0 11507 0
[pid=25113/tid=25118] ppid=25112 vsize=144680 CPUtime=0.21
/proc/25113/task/25118/stat : 25118 (aptitude) R 25112 25113 17863 34816 17863 4202560 2825 2201 0 6 20 0 0 1 20 0 2 0 29350179 148152320 19895 18446744073709551615 140439067705344 140439072012696 140736106837408 140438955372696 140439070419935 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.15
Current children cumulated vsize (KiB) 144680

[startup+6.80024 s]
/proc/loadavg: 1.20 1.11 1.04 2/57 25119
/proc/meminfo: memFree=795660/1022884 swapFree=0/0
[pid=25113] ppid=25112 vsize=149828 CPUtime=3.53
/proc/25113/stat : 25113 (aptitude) D 25112 25113 17863 34816 17863 4202496 26044 2201 323 6 334 18 0 1 20 0 2 0 29349779 153423872 21174 18446744073709551615 140439067705344 140439072012696 140736106837408 140736106829096 140439052641744 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 315 0 0
/proc/25113/statm: 37457 21174 10362 1052 0 12794 0
[pid=25113/tid=25118] ppid=25112 vsize=149828 CPUtime=0.58
/proc/25113/task/25118/stat : 25118 (aptitude) S 25112 25113 17863 34816 17863 4202560 4629 2201 1 6 56 1 0 1 20 0 2 0 29350179 153423872 21174 18446744073709551615 140439067705344 140439072012696 140736106837408 140438955382784 140439036449492 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 3.53
Current children cumulated vsize (KiB) 149828

[startup+7.20034 s]
/proc/loadavg: 1.20 1.11 1.04 2/57 25119
/proc/meminfo: memFree=795660/1022884 swapFree=0/0
[pid=25113] ppid=25112 vsize=76140 CPUtime=3.81
/proc/25113/stat : 25113 (aptitude) D 25112 25113 17863 34816 17863 4202496 28789 2700 342 6 358 22 0 1 20 0 1 0 29349779 77967360 2842 18446744073709551615 140439067705344 140439072012696 140736106837408 140736106836968 140439068735872 0 134217728 4096 0 0 0 0 17 0 0 0 326 0 0
/proc/25113/statm: 19035 2842 1507 1052 0 3291 0
Current children cumulated CPU time (s) 3.81
Current children cumulated vsize (KiB) 76140

Child status: 0
Real time (s): 7.22408
CPU time (s): 3.82424
CPU user time (s): 3.59222
CPU system time (s): 0.232014
CPU usage (%): 52.9373
Max. virtual memory (cumulated for all children) (KiB): 149988

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.59222
system time used= 0.232014
maximum resident set size= 84996
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 31537
page faults= 357
swaps= 0
block input operations= 255688
block output operations= 8
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2506
involuntary context switches= 112

runsolver used 0.016001 second user time and 0.028001 second system time

The end