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/logs/69.runsolver.aptitude aptitude -s -y --without-recommends install libforms-dev libdbd-mysql-ruby libxmp2 libinline-octave-perl libgnomeada2-dev 

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.05 0.97 2/55 21686
/proc/meminfo: memFree=910116/1022884 swapFree=0/0
[pid=21686] ppid=21685 vsize=3152 CPUtime=0
/proc/21686/stat : 21686 (runsolver) R 21685 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28528383 3227648 32 18446744073709551615 134512640 134586868 4290012176 4290010224 4152165424 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/21686/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.144037 s]
/proc/loadavg: 1.05 1.05 0.97 2/55 21686
/proc/meminfo: memFree=910116/1022884 swapFree=0/0
[pid=21686] ppid=21685 vsize=89152 CPUtime=0.14
/proc/21686/stat : 21686 (aptitude) R 21685 21686 17863 34816 17863 4202496 7773 1709 0 0 11 2 1 0 20 0 1 0 28528383 91291648 7573 18446744073709551615 140453697003520 140453701310872 140733258181888 140733258173152 140453691844072 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21686/statm: 22288 7573 6662 1052 0 858 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 89152

[startup+0.200291 s]
/proc/loadavg: 1.05 1.05 0.97 2/55 21686
/proc/meminfo: memFree=910116/1022884 swapFree=0/0
[pid=21686] ppid=21685 vsize=89152 CPUtime=0.19
/proc/21686/stat : 21686 (aptitude) R 21685 21686 17863 34816 17863 4202496 7870 1709 0 0 16 2 1 0 20 0 1 0 28528383 91291648 7662 18446744073709551615 140453697003520 140453701310872 140733258181888 140733258171664 140453692403261 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21686/statm: 22288 7662 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 89152

[startup+0.300272 s]
/proc/loadavg: 1.05 1.05 0.97 2/55 21686
/proc/meminfo: memFree=910116/1022884 swapFree=0/0
[pid=21686] ppid=21685 vsize=101864 CPUtime=0.29
/proc/21686/stat : 21686 (aptitude) R 21685 21686 17863 34816 17863 4202496 11709 1709 0 0 25 3 1 0 20 0 1 0 28528383 104308736 10756 18446744073709551615 140453697003520 140453701310872 140733258181888 140733258171320 140453691904119 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21686/statm: 25466 10756 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 101864

[startup+0.700211 s]
/proc/loadavg: 1.05 1.05 0.97 2/55 21686
/proc/meminfo: memFree=910116/1022884 swapFree=0/0
[pid=21686] ppid=21685 vsize=108400 CPUtime=0.69
/proc/21686/stat : 21686 (aptitude) R 21685 21686 17863 34816 17863 4202496 12284 1709 0 0 63 5 1 0 20 0 2 0 28528383 111001600 10656 18446744073709551615 140453697003520 140453701310872 140733258181888 140733258177384 140453655155968 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21686/statm: 27100 10656 6955 1052 0 5670 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 108400

[startup+1.50024 s]
/proc/loadavg: 1.05 1.05 0.97 2/57 21691
/proc/meminfo: memFree=889276/1022884 swapFree=0/0
[pid=21686] ppid=21685 vsize=115432 CPUtime=1.48
/proc/21686/stat : 21686 (aptitude) R 21685 21686 17863 34816 17863 4202496 14514 2207 0 0 140 7 1 0 20 0 2 0 28528383 118202368 12370 18446744073709551615 140453697003520 140453701310872 140733258181888 140733258173912 140453699711585 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21686/statm: 28858 12370 7073 1052 0 7428 0
[pid=21686/tid=21691] ppid=21685 vsize=115432 CPUtime=0.01
/proc/21686/task/21691/stat : 21691 (aptitude) S 21685 21686 17863 34816 17863 4202560 6 2207 0 0 0 0 1 0 20 0 2 0 28528428 118202368 12370 18446744073709551615 140453697003520 140453701310872 140733258181888 140453600409600 140453665747668 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) 115432

[startup+3.10024 s]
/proc/loadavg: 1.05 1.05 0.97 2/57 21692
/proc/meminfo: memFree=883200/1022884 swapFree=0/0
[pid=21686] ppid=21685 vsize=136816 CPUtime=3.07
/proc/21686/stat : 21686 (aptitude) S 21685 21686 17863 34816 17863 4202496 20993 2207 0 0 296 10 1 0 20 0 2 0 28528383 140099584 17936 18446744073709551615 140453697003520 140453701310872 140733258181888 140733258173648 140453665748555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21686/statm: 34204 17936 7129 1052 0 12774 0
[pid=21686/tid=21691] ppid=21685 vsize=136816 CPUtime=1.05
/proc/21686/task/21691/stat : 21691 (aptitude) R 21685 21686 17863 34816 17863 4202560 6334 2207 0 0 100 4 1 0 20 0 2 0 28528428 140099584 17936 18446744073709551615 140453697003520 140453701310872 140733258181888 140453600401048 140453654513760 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) 136816

[startup+6.30024 s]
/proc/loadavg: 1.05 1.05 0.97 2/57 21692
/proc/meminfo: memFree=837072/1022884 swapFree=0/0
[pid=21686] ppid=21685 vsize=241056 CPUtime=6.27
/proc/21686/stat : 21686 (aptitude) S 21685 21686 17863 34816 17863 4202496 30666 2207 0 0 610 16 1 0 20 0 2 0 28528383 246841344 27606 18446744073709551615 140453697003520 140453701310872 140733258181888 140733258173648 140453665748555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21686/statm: 60264 27606 7129 1052 0 38834 0
[pid=21686/tid=21691] ppid=21685 vsize=241056 CPUtime=4.23
/proc/21686/task/21691/stat : 21691 (aptitude) R 21685 21686 17863 34816 17863 4202560 16006 2207 0 0 414 8 1 0 20 0 2 0 28528428 246841344 27606 18446744073709551615 140453697003520 140453701310872 140733258181888 140453600401096 140453654513991 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 241056

[startup+12.7002 s]
/proc/loadavg: 1.04 1.05 0.97 2/57 21692
/proc/meminfo: memFree=754364/1022884 swapFree=0/0
[pid=21686] ppid=21685 vsize=323388 CPUtime=12.64
/proc/21686/stat : 21686 (aptitude) S 21685 21686 17863 34816 17863 4202496 51229 2207 0 0 1238 25 1 0 20 0 2 0 28528383 331149312 48163 18446744073709551615 140453697003520 140453701310872 140733258181888 140733258173648 140453665748555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21686/statm: 80847 48163 7129 1052 0 59417 0
[pid=21686/tid=21691] ppid=21685 vsize=323388 CPUtime=10.6
/proc/21686/task/21691/stat : 21691 (aptitude) R 21685 21686 17863 34816 17863 4202560 36569 2207 0 0 1041 18 1 0 20 0 2 0 28528428 331149312 48163 18446744073709551615 140453697003520 140453701310872 140733258181888 140453600401272 140453654514016 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.64
Current children cumulated vsize (KiB) 323388

[startup+25.5003 s]
/proc/loadavg: 1.03 1.04 0.97 2/57 21692
/proc/meminfo: memFree=667440/1022884 swapFree=0/0
[pid=21686] ppid=21685 vsize=402176 CPUtime=25.37
/proc/21686/stat : 21686 (aptitude) S 21685 21686 17863 34816 17863 4202496 71069 2207 0 0 2504 32 1 0 20 0 2 0 28528383 411828224 67849 18446744073709551615 140453697003520 140453701310872 140733258181888 140733258173648 140453665748555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21686/statm: 100544 67849 7129 1052 0 79114 0
[pid=21686/tid=21691] ppid=21685 vsize=402176 CPUtime=23.34
/proc/21686/task/21691/stat : 21691 (aptitude) R 21685 21686 17863 34816 17863 4202560 56409 2207 0 0 2308 25 1 0 20 0 2 0 28528428 411828224 67849 18446744073709551615 140453697003520 140453701310872 140733258181888 140453600400872 140453699636699 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) 402176

[startup+51.1003 s]
/proc/loadavg: 1.02 1.04 0.97 2/57 21692
/proc/meminfo: memFree=541084/1022884 swapFree=0/0
[pid=21686] ppid=21685 vsize=529536 CPUtime=50.86
/proc/21686/stat : 21686 (aptitude) S 21685 21686 17863 34816 17863 4202496 102884 2207 0 0 5039 46 1 0 20 0 2 0 28528383 542244864 99660 18446744073709551615 140453697003520 140453701310872 140733258181888 140733258173648 140453665748555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21686/statm: 132384 99660 7143 1052 0 110954 0
[pid=21686/tid=21691] ppid=21685 vsize=529536 CPUtime=48.83
/proc/21686/task/21691/stat : 21691 (aptitude) R 21685 21686 17863 34816 17863 4202560 88217 2207 0 0 4843 39 1 0 20 0 2 0 28528428 542244864 99660 18446744073709551615 140453697003520 140453701310872 140733258181888 140453600400920 140453654513991 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 50.86
Current children cumulated vsize (KiB) 529536

[startup+102.3 s]
/proc/loadavg: 1.01 1.03 0.97 2/57 21692
/proc/meminfo: memFree=212608/1022884 swapFree=0/0
[pid=21686] ppid=21685 vsize=855408 CPUtime=101.83
/proc/21686/stat : 21686 (aptitude) S 21685 21686 17863 34816 17863 4202496 184300 2207 0 0 10097 85 1 0 20 0 2 0 28528383 875937792 181019 18446744073709551615 140453697003520 140453701310872 140733258181888 140733258173648 140453665748555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21686/statm: 213852 181019 7145 1052 0 192422 0
[pid=21686/tid=21691] ppid=21685 vsize=855408 CPUtime=99.8
/proc/21686/task/21691/stat : 21691 (aptitude) R 21685 21686 17863 34816 17863 4202560 169633 2207 0 0 9901 78 1 0 20 0 2 0 28528428 875937792 181019 18446744073709551615 140453697003520 140453701310872 140733258181888 140453600400920 140453654513957 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 101.83
Current children cumulated vsize (KiB) 855408



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+135.7 s]
/proc/loadavg: 1.22 1.07 0.99 2/57 21692
/proc/meminfo: memFree=10184/1022884 swapFree=0/0
[pid=21686] ppid=21685 vsize=1151564 CPUtime=133.17
/proc/21686/stat : 21686 (aptitude) S 21685 21686 17863 34816 17863 4202496 258860 2207 244 0 13190 126 1 0 20 0 2 0 28528383 1179201536 245107 18446744073709551615 140453697003520 140453701310872 140733258181888 140733258173648 140453665748555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21686/statm: 287891 245107 4009 1052 0 266461 0
[pid=21686/tid=21691] ppid=21685 vsize=1151564 CPUtime=131.12
/proc/21686/task/21691/stat : 21691 (aptitude) R 21685 21686 17863 34816 17863 4202560 244193 2207 244 0 12992 119 1 0 20 0 2 0 28528428 1179201536 245107 18446744073709551615 140453697003520 140453701310872 140733258181888 140453600400920 140453699762627 0 134217728 4096 0 0 0 0 -1 0 0 0 164 0 0
Current children cumulated CPU time (s) 133.17
Current children cumulated vsize (KiB) 1151564

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

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

Child ended because it received signal 15 (SIGTERM)
Real time (s): 135.821
CPU time (s): 133.284
CPU user time (s): 131.944
CPU system time (s): 1.34008
CPU usage (%): 98.1322
Max. virtual memory (cumulated for all children) (KiB): 1151564

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 131.944
system time used= 1.34008
maximum resident set size= 982152
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 261124
page faults= 244
swaps= 0
block input operations= 26264
block output operations= 56
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 634
involuntary context switches= 2704

runsolver used 0.192012 second user time and 0.428026 second system time

The end