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


[startup+0 s]
/proc/loadavg: 1.14 1.13 1.07 2/55 26057
/proc/meminfo: memFree=911856/1022884 swapFree=0/0
[pid=26057] ppid=26056 vsize=3152 CPUtime=0
/proc/26057/stat : 26057 (runsolver) D 26056 26057 17863 34816 17863 4202560 80 0 0 0 0 0 0 0 20 0 1 0 29675320 3227648 102 18446744073709551615 134512640 134586868 4287656976 4287654944 4151489584 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/26057/statm: 788 102 69 19 0 73 0

[startup+0.184545 s]
/proc/loadavg: 1.14 1.13 1.07 2/55 26057
/proc/meminfo: memFree=911856/1022884 swapFree=0/0
[pid=26057] ppid=26056 vsize=17468 CPUtime=0
/proc/26057/stat : 26057 (aptitude) D 26056 26057 17863 34816 17863 4202496 134 0 8 0 0 0 0 0 20 0 1 0 29675320 17887232 57 18446744073709551615 139801058967552 139801063274904 140736006708752 140736006705560 139801056826758 0 0 0 0 0 0 0 17 0 0 0 17 0 0
/proc/26057/statm: 4367 57 40 1052 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 17468

[startup+0.200277 s]
/proc/loadavg: 1.14 1.13 1.07 2/55 26057
/proc/meminfo: memFree=911856/1022884 swapFree=0/0
[pid=26057] ppid=26056 vsize=23840 CPUtime=0
/proc/26057/stat : 26057 (aptitude) D 26056 26057 17863 34816 17863 4202496 143 0 11 0 0 0 0 0 20 0 1 0 29675320 24412160 67 18446744073709551615 139801058967552 139801063274904 140736006708752 140736006705464 139801056826126 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/26057/statm: 5960 67 45 1052 0 31 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 23840

[startup+0.300366 s]
/proc/loadavg: 1.14 1.13 1.07 2/55 26057
/proc/meminfo: memFree=911856/1022884 swapFree=0/0
[pid=26057] ppid=26056 vsize=36128 CPUtime=0
/proc/26057/stat : 26057 (aptitude) D 26056 26057 17863 34816 17863 4202496 166 0 21 0 0 0 0 0 20 0 1 0 29675320 36995072 95 18446744073709551615 139801058967552 139801063274904 140736006708752 140736006705576 139801056823490 0 0 0 0 0 0 0 17 0 0 0 29 0 0
/proc/26057/statm: 9032 95 60 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 36128

[startup+0.700288 s]
/proc/loadavg: 1.14 1.13 1.07 2/55 26057
/proc/meminfo: memFree=911856/1022884 swapFree=0/0
[pid=26057] ppid=26056 vsize=54968 CPUtime=0.01
/proc/26057/stat : 26057 (aptitude) D 26056 26057 17863 34816 17863 4202496 1020 0 65 0 1 0 0 0 20 0 1 0 29675320 56287232 975 18446744073709551615 139801058967552 139801063274904 140736006708752 140736006704776 139801016743632 0 134217728 4096 0 0 0 0 17 0 0 0 67 0 0
/proc/26057/statm: 13742 975 814 1052 0 106 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 54968

[startup+1.5002 s]
/proc/loadavg: 1.14 1.13 1.07 1/56 26061
/proc/meminfo: memFree=897704/1022884 swapFree=0/0
[pid=26057] ppid=26056 vsize=103288 CPUtime=0.04
/proc/26057/stat : 26057 (aptitude) D 26056 26057 17863 34816 17863 4202496 3034 1704 161 4 1 2 1 0 20 0 1 0 29675320 105766912 2996 18446744073709551615 139801058967552 139801063274904 140736006708752 140736006700224 139801054017434 0 134217728 4096 0 0 0 0 17 0 0 0 140 0 0
/proc/26057/statm: 25822 2996 1784 1052 0 1159 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 103288

[startup+3.10021 s]
/proc/loadavg: 1.14 1.13 1.07 1/56 26061
/proc/meminfo: memFree=894356/1022884 swapFree=0/0
[pid=26057] ppid=26056 vsize=103288 CPUtime=0.28
/proc/26057/stat : 26057 (aptitude) R 26056 26057 17863 34816 17863 4202496 10927 1704 377 4 24 3 1 0 20 0 1 0 29675320 105766912 11105 18446744073709551615 139801058967552 139801063274904 140736006708752 140736006700016 139801053811120 0 134217728 4096 0 0 0 0 17 0 0 0 277 0 0
/proc/26057/statm: 25822 11105 9893 1052 0 1159 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 103288
heavy processes:

[startup+6.30023 s]
/proc/loadavg: 1.13 1.12 1.07 2/57 26062
/proc/meminfo: memFree=745424/1022884 swapFree=0/0
[pid=26057] ppid=26056 vsize=137840 CPUtime=2.47
/proc/26057/stat : 26057 (aptitude) R 26056 26057 17863 34816 17863 4202496 20472 1704 393 4 232 14 1 0 20 0 2 0 29675320 141148160 17780 18446744073709551615 139801058967552 139801063274904 140736006708752 140736006700408 139801016477712 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 376 0 0
/proc/26057/statm: 34460 17780 10273 1052 0 9797 0
[pid=26057/tid=26062] ppid=26056 vsize=137840 CPUtime=0.01
/proc/26057/task/26062/stat : 26062 (aptitude) S 26056 26057 17863 34816 17863 4202560 4 1704 0 4 0 0 1 0 20 0 2 0 29675778 141148160 17780 18446744073709551615 139801058967552 139801063274904 140736006708752 139800946644992 139801027711700 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 2.47
Current children cumulated vsize (KiB) 137840
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.12 1.12 1.07 2/57 26063
/proc/meminfo: memFree=680324/1022884 swapFree=0/0
[pid=26057] ppid=26056 vsize=272064 CPUtime=8.8
/proc/26057/stat : 26057 (aptitude) S 26056 26057 17863 34816 17863 4202496 39545 2202 395 5 853 26 1 0 20 0 2 0 29675320 278593536 35332 18446744073709551615 139801058967552 139801063274904 140736006708752 140736006700512 139801027712587 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 378 0 0
/proc/26057/statm: 68016 35332 10359 1052 0 43353 0
[pid=26057/tid=26062] ppid=26056 vsize=272064 CPUtime=5.31
/proc/26057/task/26062/stat : 26062 (aptitude) R 26056 26057 17863 34816 17863 4202560 17922 2202 0 5 522 8 1 0 20 0 2 0 29675778 278593536 35332 18446744073709551615 139801058967552 139801063274904 140736006708752 139800946638520 139801061674804 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 8.8
Current children cumulated vsize (KiB) 272064
heavy processes:

[startup+25.5003 s]
/proc/loadavg: 1.09 1.12 1.07 2/57 26063
/proc/meminfo: memFree=590548/1022884 swapFree=0/0
[pid=26057] ppid=26056 vsize=357056 CPUtime=21.54
/proc/26057/stat : 26057 (aptitude) S 26056 26057 17863 34816 17863 4202496 61000 2202 395 5 2114 39 1 0 20 0 2 0 29675320 365625344 56597 18446744073709551615 139801058967552 139801063274904 140736006708752 140736006700512 139801027712587 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 378 0 0
/proc/26057/statm: 89264 56597 10360 1052 0 64601 0
[pid=26057/tid=26062] ppid=26056 vsize=357056 CPUtime=18.04
/proc/26057/task/26062/stat : 26062 (aptitude) R 26056 26057 17863 34816 17863 4202560 39377 2202 0 5 1782 21 1 0 20 0 2 0 29675778 365625344 56597 18446744073709551615 139801058967552 139801063274904 140736006708752 139800946636312 139801061196992 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 21.54
Current children cumulated vsize (KiB) 357056

[startup+51.1003 s]
/proc/loadavg: 1.06 1.11 1.06 2/57 26063
/proc/meminfo: memFree=410128/1022884 swapFree=0/0
[pid=26057] ppid=26056 vsize=539872 CPUtime=47.02
/proc/26057/stat : 26057 (aptitude) S 26056 26057 17863 34816 17863 4202496 107363 2202 395 5 4641 60 1 0 20 0 2 0 29675320 552828928 102231 18446744073709551615 139801058967552 139801063274904 140736006708752 140736006700512 139801027712587 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 378 0 0
/proc/26057/statm: 134968 102231 10374 1052 0 110305 0
[pid=26057/tid=26062] ppid=26056 vsize=539872 CPUtime=43.52
/proc/26057/task/26062/stat : 26062 (aptitude) R 26056 26057 17863 34816 17863 4202560 85733 2202 0 5 4309 42 1 0 20 0 2 0 29675778 552828928 102231 18446744073709551615 139801058967552 139801063274904 140736006708752 139800946638520 139801061674789 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 47.02
Current children cumulated vsize (KiB) 539872

[startup+102.303 s]
/proc/loadavg: 1.02 1.09 1.06 2/57 26063
/proc/meminfo: memFree=8264/1022884 swapFree=0/0
[pid=26057] ppid=26056 vsize=947824 CPUtime=97.49
/proc/26057/stat : 26057 (aptitude) S 26056 26057 17863 34816 17863 4202496 209371 2202 395 5 9637 111 1 0 20 0 2 0 29675320 970571776 204154 18446744073709551615 139801058967552 139801063274904 140736006708752 140736006700512 139801027712587 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 378 0 0
/proc/26057/statm: 236956 204154 10375 1052 0 212293 0
[pid=26057/tid=26062] ppid=26056 vsize=947824 CPUtime=93.98
/proc/26057/task/26062/stat : 26062 (aptitude) R 26056 26057 17863 34816 17863 4202560 187741 2202 0 5 9304 93 1 0 20 0 2 0 29675778 970571776 204154 18446744073709551615 139801058967552 139801063274904 140736006708752 139800946636360 139801061695945 0 134217728 4096 0 0 0 0 -1 0 0 0 49 0 0
Current children cumulated CPU time (s) 97.49
Current children cumulated vsize (KiB) 947824



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+124.703 s]
/proc/loadavg: 1.08 1.09 1.06 2/57 26063
/proc/meminfo: memFree=9812/1022884 swapFree=0/0
[pid=26057] ppid=26056 vsize=1151488 CPUtime=119.18
/proc/26057/stat : 26057 (aptitude) S 26056 26057 17863 34816 17863 4202496 260052 2202 405 5 11777 140 1 0 20 0 2 0 29675320 1179123712 245446 18446744073709551615 139801058967552 139801063274904 140736006708752 140736006700512 139801027712587 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 379 0 0
/proc/26057/statm: 287872 245446 10246 1052 0 263209 0
[pid=26057/tid=26062] ppid=26056 vsize=1151488 CPUtime=115.67
/proc/26057/task/26062/stat : 26062 (aptitude) R 26056 26057 17863 34816 17863 4202560 238422 2202 10 5 11444 122 1 0 20 0 2 0 29675778 1179123712 245446 18446744073709551615 139801058967552 139801063274904 140736006708752 139800946638520 139801061858707 0 134217728 4096 0 0 0 0 -1 0 0 0 63 0 0
Current children cumulated CPU time (s) 119.18
Current children cumulated vsize (KiB) 1151488

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

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

[startup+124.703 s]
/proc/loadavg: 1.08 1.09 1.06 2/57 26063
/proc/meminfo: memFree=9812/1022884 swapFree=0/0
[pid=26057] ppid=26056 vsize=1151488 CPUtime=119.18
/proc/26057/stat : 26057 (aptitude) S 26056 26057 17863 34816 17863 4202496 260052 2202 405 5 11777 140 1 0 20 0 2 0 29675320 1179123712 245446 18446744073709551615 139801058967552 139801063274904 140736006708752 140736006700512 139801027712587 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 379 0 0
/proc/26057/statm: 287872 245446 10246 1052 0 263209 0
[pid=26057/tid=26062] ppid=26056 vsize=1151488 CPUtime=115.67
/proc/26057/task/26062/stat : 26062 (aptitude) R 26056 26057 17863 34816 17863 4202560 238422 2202 10 5 11444 122 1 0 20 0 2 0 29675778 1179123712 245446 18446744073709551615 139801058967552 139801063274904 140736006708752 139800946638520 139801061858707 0 134217728 4096 0 0 0 0 -1 0 0 0 63 0 0
Current children cumulated CPU time (s) 119.18
Current children cumulated vsize (KiB) 1151488

Child ended because it received signal 15 (SIGTERM)
Real time (s): 124.815
CPU time (s): 119.291
CPU user time (s): 117.815
CPU system time (s): 1.47609
CPU usage (%): 95.5745
Max. virtual memory (cumulated for all children) (KiB): 1151488

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 117.815
system time used= 1.47609
maximum resident set size= 982032
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262296
page faults= 410
swaps= 0
block input operations= 273432
block output operations= 80
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2866
involuntary context switches= 2769

runsolver used 0.176011 second user time and 0.404025 second system time

The end