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/83.runsolver.aptitude aptitude -s -y --without-recommends install pgmonitor affix-source smpeg-xmms alicq libtemplate-plugin-calendar-simple-perl 

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.05 1.06 1.01 2/55 23882
/proc/meminfo: memFree=869724/1022884 swapFree=0/0
[pid=23882] ppid=23881 vsize=3152 CPUtime=0
/proc/23882/stat : 23882 (runsolver) R 23881 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29097427 3227648 32 18446744073709551615 134512640 134586868 4290388448 4290386496 4151223344 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23882/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.126113 s]
/proc/loadavg: 1.05 1.06 1.01 2/55 23882
/proc/meminfo: memFree=869724/1022884 swapFree=0/0
[pid=23882] ppid=23881 vsize=100508 CPUtime=0.12
/proc/23882/stat : 23882 (aptitude) R 23881 23882 17863 34816 17863 4202496 10559 1708 0 0 9 2 1 0 20 0 1 0 29097427 102920192 10360 18446744073709551615 139813372203008 139813376510360 140737395156624 140737395147888 139813367043659 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23882/statm: 25127 10360 9186 1052 0 1122 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 100508

[startup+0.200273 s]
/proc/loadavg: 1.05 1.06 1.01 2/55 23882
/proc/meminfo: memFree=869724/1022884 swapFree=0/0
[pid=23882] ppid=23881 vsize=100508 CPUtime=0.2
/proc/23882/stat : 23882 (aptitude) R 23881 23882 17863 34816 17863 4202496 10605 1708 0 0 17 2 1 0 20 0 1 0 29097427 102920192 10406 18446744073709551615 139813372203008 139813376510360 140737395156624 140737395147888 139813366898416 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23882/statm: 25127 10406 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 100508

[startup+0.300267 s]
/proc/loadavg: 1.05 1.06 1.01 2/55 23882
/proc/meminfo: memFree=869724/1022884 swapFree=0/0
[pid=23882] ppid=23881 vsize=111108 CPUtime=0.29
/proc/23882/stat : 23882 (aptitude) R 23881 23882 17863 34816 17863 4202496 12550 1708 0 0 26 2 1 0 20 0 1 0 29097427 113774592 12343 18446744073709551615 139813372203008 139813376510360 140737395156624 140737395148216 139813374334555 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23882/statm: 27777 12343 9302 1052 0 3772 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 111108

[startup+0.700195 s]
/proc/loadavg: 1.05 1.06 1.01 2/55 23882
/proc/meminfo: memFree=869724/1022884 swapFree=0/0
[pid=23882] ppid=23881 vsize=123288 CPUtime=0.69
/proc/23882/stat : 23882 (aptitude) R 23881 23882 17863 34816 17863 4202496 17027 1708 0 0 63 5 1 0 20 0 2 0 29097427 126246912 14302 18446744073709551615 139813372203008 139813376510360 140737395156624 140737395152408 139813367046136 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23882/statm: 30822 14302 9482 1052 0 6817 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 123288

[startup+1.50023 s]
/proc/loadavg: 1.05 1.06 1.01 2/57 23887
/proc/meminfo: memFree=841444/1022884 swapFree=0/0
[pid=23882] ppid=23881 vsize=132416 CPUtime=1.49
/proc/23882/stat : 23882 (aptitude) R 23881 23882 17863 34816 17863 4202496 19439 1708 0 0 142 6 1 0 20 0 2 0 29097427 135593984 16710 18446744073709551615 139813372203008 139813376510360 140737395156624 140737395146976 139813329713242 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23882/statm: 33104 16710 9585 1052 0 9099 0
[pid=23882/tid=23887] ppid=23881 vsize=132416 CPUtime=0.01
/proc/23882/task/23887/stat : 23887 (aptitude) S 23881 23882 17863 34816 17863 4202560 4 1708 0 0 0 0 1 0 20 0 2 0 29097492 135593984 16710 18446744073709551615 139813372203008 139813376510360 140737395156624 139813263030272 139813340947156 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 132416

[startup+3.10024 s]
/proc/loadavg: 1.05 1.06 1.01 2/57 23888
/proc/meminfo: memFree=840320/1022884 swapFree=0/0
[pid=23882] ppid=23881 vsize=133828 CPUtime=3.08
/proc/23882/stat : 23882 (aptitude) R 23881 23882 17863 34816 17863 4202496 20619 2207 0 0 295 12 1 0 20 0 2 0 29097427 137039872 16946 18446744073709551615 139813372203008 139813376510360 140737395156624 140737395143440 139813367030768 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23882/statm: 33457 16946 9644 1052 0 9452 0
[pid=23882/tid=23887] ppid=23881 vsize=133828 CPUtime=0.01
/proc/23882/task/23887/stat : 23887 (aptitude) S 23881 23882 17863 34816 17863 4202560 6 2207 0 0 0 0 1 0 20 0 2 0 29097492 137039872 16946 18446744073709551615 139813372203008 139813376510360 140737395156624 139813263030272 139813340947156 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 133828

[startup+6.30024 s]
/proc/loadavg: 1.05 1.06 1.00 2/57 23888
/proc/meminfo: memFree=796680/1022884 swapFree=0/0
[pid=23882] ppid=23881 vsize=245856 CPUtime=6.26
/proc/23882/stat : 23882 (aptitude) S 23881 23882 17863 34816 17863 4202496 33215 2207 0 0 608 17 1 0 20 0 2 0 29097427 251756544 28798 18446744073709551615 139813372203008 139813376510360 140737395156624 140737395148384 139813340948043 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23882/statm: 61464 28798 9700 1052 0 37459 0
[pid=23882/tid=23887] ppid=23881 vsize=245856 CPUtime=3.16
/proc/23882/task/23887/stat : 23887 (aptitude) R 23881 23882 17863 34816 17863 4202560 12595 2207 0 0 310 5 1 0 20 0 2 0 29097492 251756544 28798 18446744073709551615 139813372203008 139813376510360 140737395156624 139813263021640 139813375033226 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.26
Current children cumulated vsize (KiB) 245856

[startup+12.7003 s]
/proc/loadavg: 1.04 1.06 1.00 2/57 23888
/proc/meminfo: memFree=750304/1022884 swapFree=0/0
[pid=23882] ppid=23881 vsize=292824 CPUtime=12.63
/proc/23882/stat : 23882 (aptitude) S 23881 23882 17863 34816 17863 4202496 45504 2207 0 0 1240 22 1 0 20 0 2 0 29097427 299851776 40528 18446744073709551615 139813372203008 139813376510360 140737395156624 140737395148384 139813340948043 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23882/statm: 73206 40528 9700 1052 0 49201 0
[pid=23882/tid=23887] ppid=23881 vsize=292824 CPUtime=9.53
/proc/23882/task/23887/stat : 23887 (aptitude) R 23881 23882 17863 34816 17863 4202560 24884 2207 0 0 942 10 1 0 20 0 2 0 29097492 299851776 40528 18446744073709551615 139813372203008 139813376510360 140737395156624 139813263021592 139813374800048 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.63
Current children cumulated vsize (KiB) 292824

[startup+25.5002 s]
/proc/loadavg: 1.03 1.05 1.00 2/57 23888
/proc/meminfo: memFree=638704/1022884 swapFree=0/0
[pid=23882] ppid=23881 vsize=401356 CPUtime=25.37
/proc/23882/stat : 23882 (aptitude) S 23881 23882 17863 34816 17863 4202496 72688 2207 0 0 2498 38 1 0 20 0 2 0 29097427 410988544 67638 18446744073709551615 139813372203008 139813376510360 140737395156624 140737395148384 139813340948043 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23882/statm: 100339 67638 9700 1052 0 76334 0
[pid=23882/tid=23887] ppid=23881 vsize=401356 CPUtime=22.27
/proc/23882/task/23887/stat : 23887 (aptitude) R 23881 23882 17863 34816 17863 4202560 52068 2207 0 0 2200 26 1 0 20 0 2 0 29097492 410988544 67638 18446744073709551615 139813372203008 139813376510360 140737395156624 139813263023800 139813329713288 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.37
Current children cumulated vsize (KiB) 401356

[startup+51.1003 s]
/proc/loadavg: 1.02 1.05 1.00 2/57 23888
/proc/meminfo: memFree=415876/1022884 swapFree=0/0
[pid=23882] ppid=23881 vsize=628388 CPUtime=50.85
/proc/23882/stat : 23882 (aptitude) S 23881 23882 17863 34816 17863 4202496 129465 2207 0 0 5023 61 1 0 20 0 2 0 29097427 643469312 124348 18446744073709551615 139813372203008 139813376510360 140737395156624 140737395148384 139813340948043 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23882/statm: 157097 124348 9716 1052 0 133092 0
[pid=23882/tid=23887] ppid=23881 vsize=628388 CPUtime=47.75
/proc/23882/task/23887/stat : 23887 (aptitude) R 23881 23882 17863 34816 17863 4202560 108839 2207 0 0 4725 49 1 0 20 0 2 0 29097492 643469312 124348 18446744073709551615 139813372203008 139813376510360 140737395156624 139813263023704 139813374899313 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 50.85
Current children cumulated vsize (KiB) 628388



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+100.303 s]
/proc/loadavg: 1.15 1.07 1.01 2/57 23888
/proc/meminfo: memFree=10388/1022884 swapFree=0/0
[pid=23882] ppid=23881 vsize=1151896 CPUtime=95.72
/proc/23882/stat : 23882 (aptitude) S 23881 23882 17863 34816 17863 4202496 260862 2207 374 0 9436 135 1 0 20 0 2 0 29097427 1179541504 246553 18446744073709551615 139813372203008 139813376510360 140737395156624 140737395148384 139813340948043 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/23882/statm: 287974 246553 8852 1052 0 263969 0
[pid=23882/tid=23887] ppid=23881 vsize=1151896 CPUtime=92.61
/proc/23882/task/23887/stat : 23887 (aptitude) R 23881 23882 17863 34816 17863 4202560 240226 2207 368 0 9137 123 1 0 20 0 2 0 29097492 1179541504 246553 18446744073709551615 139813372203008 139813376510360 140737395156624 139813263021896 139813374905311 0 134217728 4096 0 0 0 0 -1 0 0 0 388 0 0
Current children cumulated CPU time (s) 95.72
Current children cumulated vsize (KiB) 1151896

Sending Terminated to process tree (bottom up)
Sleeping 2 seconds

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

[startup+100.303 s]
/proc/loadavg: 1.15 1.07 1.01 2/57 23888
/proc/meminfo: memFree=10388/1022884 swapFree=0/0
[pid=23882] ppid=23881 vsize=1151896 CPUtime=95.72
/proc/23882/stat : 23882 (aptitude) S 23881 23882 17863 34816 17863 4202496 260862 2207 374 0 9436 135 1 0 20 0 2 0 29097427 1179541504 246553 18446744073709551615 139813372203008 139813376510360 140737395156624 140737395148384 139813340948043 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0
/proc/23882/statm: 287974 246553 8852 1052 0 263969 0
[pid=23882/tid=23887] ppid=23881 vsize=1151896 CPUtime=92.61
/proc/23882/task/23887/stat : 23887 (aptitude) R 23881 23882 17863 34816 17863 4202560 240226 2207 368 0 9137 123 1 0 20 0 2 0 29097492 1179541504 246553 18446744073709551615 139813372203008 139813376510360 140737395156624 139813263021896 139813374905311 0 134217728 4096 0 0 0 0 -1 0 0 0 388 0 0
Current children cumulated CPU time (s) 95.72
Current children cumulated vsize (KiB) 1151896

Child ended because it received signal 15 (SIGTERM)
Real time (s): 100.428
CPU time (s): 95.842
CPU user time (s): 94.4179
CPU system time (s): 1.42409
CPU usage (%): 95.4336
Max. virtual memory (cumulated for all children) (KiB): 1151896

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 94.4179
system time used= 1.42409
maximum resident set size= 988128
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 263158
page faults= 374
swaps= 0
block input operations= 14816
block output operations= 64
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 703
involuntary context switches= 2228

runsolver used 0.292018 second user time and 0.384024 second system time

The end