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/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
Current StackSize limit: 8192 KiB


[startup+0.133918 s]
/proc/loadavg: 1.07 1.06 1.01 2/55 23037
/proc/meminfo: memFree=962716/1022884 swapFree=0/0
[pid=23037] ppid=23036 vsize=28716 CPUtime=0
/proc/23037/stat : 23037 (aptitude) D 23036 23037 17863 34816 17863 4202496 155 0 11 0 0 0 0 0 20 0 1 0 28790169 29405184 78 18446744073709551615 139994156318720 139994160626072 140736526634032 140736526630648 139994154178083 0 0 0 0 0 0 0 17 0 0 0 12 0 0
/proc/23037/statm: 7179 78 50 1052 0 33 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 28716

[startup+0.200389 s]
/proc/loadavg: 1.07 1.06 1.01 2/55 23037
/proc/meminfo: memFree=962716/1022884 swapFree=0/0
[pid=23037] ppid=23036 vsize=40832 CPUtime=0
/proc/23037/stat : 23037 (aptitude) D 23036 23037 17863 34816 17863 4202496 177 0 16 0 0 0 0 0 20 0 1 0 28790169 41811968 101 18446744073709551615 139994156318720 139994160626072 140736526634032 140736526630456 139994154178083 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/23037/statm: 10208 101 63 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 40832

[startup+0.300375 s]
/proc/loadavg: 1.07 1.06 1.01 2/55 23037
/proc/meminfo: memFree=962716/1022884 swapFree=0/0
[pid=23037] ppid=23036 vsize=54968 CPUtime=0
/proc/23037/stat : 23037 (aptitude) D 23036 23037 17863 34816 17863 4202496 1087 0 25 0 0 0 0 0 20 0 1 0 28790169 56287232 1003 18446744073709551615 139994156318720 139994160626072 140736526634032 140736526630072 139994114163968 0 134217728 4096 0 0 0 0 17 0 0 0 28 0 0
/proc/23037/statm: 13742 1003 833 1052 0 106 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54968

[startup+0.700271 s]
/proc/loadavg: 1.07 1.06 1.01 2/55 23037
/proc/meminfo: memFree=962716/1022884 swapFree=0/0
[pid=23037] ppid=23036 vsize=100508 CPUtime=0.03
/proc/23037/stat : 23037 (aptitude) D 23036 23037 17863 34816 17863 4202496 2717 1705 64 4 0 2 1 0 20 0 1 0 28790169 102920192 2583 18446744073709551615 139994156318720 139994160626072 140736526634032 140736526625504 139994151368602 0 134217728 4096 0 0 0 0 17 0 0 0 64 0 0
/proc/23037/statm: 25127 2583 1408 1052 0 1122 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 100508

[startup+1.50029 s]
/proc/loadavg: 1.07 1.06 1.01 1/56 23041
/proc/meminfo: memFree=954392/1022884 swapFree=0/0
[pid=23037] ppid=23036 vsize=100508 CPUtime=0.03
/proc/23037/stat : 23037 (aptitude) D 23036 23037 17863 34816 17863 4202496 5616 1705 198 4 0 2 1 0 20 0 1 0 28790169 102920192 5616 18446744073709551615 139994156318720 139994160626072 140736526634032 140736526625504 139994151368602 0 134217728 4096 0 0 0 0 17 0 0 0 143 0 0
/proc/23037/statm: 25127 5616 4441 1052 0 1122 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 100508

[startup+3.10021 s]
/proc/loadavg: 1.07 1.06 1.01 2/56 23041
/proc/meminfo: memFree=939760/1022884 swapFree=0/0
[pid=23037] ppid=23036 vsize=123288 CPUtime=0.77
/proc/23037/stat : 23037 (aptitude) R 23036 23037 17863 34816 17863 4202496 16786 1705 258 4 58 18 1 0 20 0 2 0 28790169 126246912 14319 18446744073709551615 139994156318720 139994160626072 140736526634032 140736526629624 139994151173356 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 230 0 0
/proc/23037/statm: 30822 14319 9496 1052 0 6817 0
Current children cumulated CPU time (s) 0.77
Current children cumulated vsize (KiB) 123288
heavy processes:

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

[startup+3.20332 s]
/proc/loadavg: 1.07 1.06 1.01 3/57 23042
/proc/meminfo: memFree=851216/1022884 swapFree=0/0
[pid=23037] ppid=23036 vsize=131768 CPUtime=0.87
/proc/23037/stat : 23037 (aptitude) R 23036 23037 17863 34816 17863 4202496 18954 1705 258 4 66 20 1 0 20 0 2 0 28790169 134930432 16484 18446744073709551615 139994156318720 139994160626072 140736526634032 140736526625304 139994157947057 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 230 0 0
/proc/23037/statm: 32942 16484 9545 1052 0 8937 0
[pid=23037/tid=23042] ppid=23036 vsize=131768 CPUtime=0.01
/proc/23037/task/23042/stat : 23042 (aptitude) S 23036 23037 17863 34816 17863 4202560 4 1705 0 4 0 0 1 0 20 0 2 0 28790472 134930432 16484 18446744073709551615 139994156318720 139994160626072 140736526634032 139994047145984 139994125062868 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 0.87
Current children cumulated vsize (KiB) 131768

[startup+4.80023 s]
/proc/loadavg: 1.06 1.05 1.01 2/57 23043
/proc/meminfo: memFree=841412/1022884 swapFree=0/0
[pid=23037] ppid=23036 vsize=133676 CPUtime=2.41
/proc/23037/stat : 23037 (aptitude) R 23036 23037 17863 34816 17863 4202496 20065 2201 258 6 220 20 1 0 20 0 2 0 28790169 136884224 16768 18446744073709551615 139994156318720 139994160626072 140736526634032 140736526620736 139994113814407 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 231 0 0
/proc/23037/statm: 33419 16768 9636 1052 0 9414 0
[pid=23037/tid=23042] ppid=23036 vsize=133676 CPUtime=0.01
/proc/23037/task/23042/stat : 23042 (aptitude) S 23036 23037 17863 34816 17863 4202560 6 2201 0 6 0 0 1 0 20 0 2 0 28790472 136884224 16768 18446744073709551615 139994156318720 139994160626072 140736526634032 139994047145984 139994125062868 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 2.41
Current children cumulated vsize (KiB) 133676

[startup+5.20024 s]
/proc/loadavg: 1.06 1.05 1.01 2/57 23043
/proc/meminfo: memFree=841412/1022884 swapFree=0/0
[pid=23037] ppid=23036 vsize=137504 CPUtime=2.81
/proc/23037/stat : 23037 (aptitude) S 23036 23037 17863 34816 17863 4202496 21988 2201 258 6 260 20 1 0 20 0 2 0 28790169 140804096 18074 18446744073709551615 139994156318720 139994160626072 140736526634032 140736526625792 139994125063755 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 231 0 0
/proc/23037/statm: 34376 18074 9691 1052 0 10371 0
[pid=23037/tid=23042] ppid=23036 vsize=137504 CPUtime=0.15
/proc/23037/task/23042/stat : 23042 (aptitude) R 23036 23037 17863 34816 17863 4202560 1924 2201 0 6 14 0 1 0 20 0 2 0 28790472 140804096 18074 18446744073709551615 139994156318720 139994160626072 140736526634032 139994047139640 139994122628075 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 2.81
Current children cumulated vsize (KiB) 137504

[startup+5.60323 s]
/proc/loadavg: 1.06 1.05 1.01 2/57 23043
/proc/meminfo: memFree=831252/1022884 swapFree=0/0
[pid=23037] ppid=23036 vsize=142812 CPUtime=3.21
/proc/23037/stat : 23037 (aptitude) R 23036 23037 17863 34816 17863 4202496 26317 2201 258 6 299 21 1 0 20 0 2 0 28790169 146239488 19466 18446744073709551615 139994156318720 139994160626072 140736526634032 140736526621896 139994158525095 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 231 0 0
/proc/23037/statm: 35703 19466 9742 1052 0 11691 0
[pid=23037/tid=23042] ppid=23036 vsize=142812 CPUtime=0.41
/proc/23037/task/23042/stat : 23042 (aptitude) S 23036 23037 17863 34816 17863 4202560 3761 2201 0 6 40 0 1 0 20 0 2 0 28790472 146239488 19466 18446744073709551615 139994156318720 139994160626072 140736526634032 139994047145984 139994125062868 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.21
Current children cumulated vsize (KiB) 142812

[startup+5.70025 s]
/proc/loadavg: 1.06 1.05 1.01 2/57 23043
/proc/meminfo: memFree=831252/1022884 swapFree=0/0
[pid=23037] ppid=23036 vsize=142812 CPUtime=3.31
/proc/23037/stat : 23037 (aptitude) R 23036 23037 17863 34816 17863 4202496 26318 2201 258 6 308 22 1 0 20 0 2 0 28790169 146239488 19466 18446744073709551615 139994156318720 139994160626072 140736526634032 140736526623792 139994114021686 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 231 0 0
/proc/23037/statm: 35703 19466 9742 1052 0 11691 0
[pid=23037/tid=23042] ppid=23036 vsize=142812 CPUtime=0.41
/proc/23037/task/23042/stat : 23042 (aptitude) S 23036 23037 17863 34816 17863 4202560 3761 2201 0 6 40 0 1 0 20 0 2 0 28790472 146239488 19466 18446744073709551615 139994156318720 139994160626072 140736526634032 139994047145984 139994125062868 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.31
Current children cumulated vsize (KiB) 142812

Child status: 0
Real time (s): 5.73285
CPU time (s): 3.35221
CPU user time (s): 3.11219
CPU system time (s): 0.240015
CPU usage (%): 58.4737
Max. virtual memory (cumulated for all children) (KiB): 142812

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.11219
system time used= 0.240015
maximum resident set size= 77876
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 29254
page faults= 264
swaps= 0
block input operations= 184296
block output operations= 8
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1887
involuntary context switches= 114

runsolver used 0.016001 second user time and 0.020001 second system time

The end