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/84.runsolver.aptitude aptitude -s -y --without-recommends install libcrypt-gpg-perl gtoaster cl-ptester libapache-mod-python2.3 opensc 

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.07 1.08 1.07 2/55 26200
/proc/meminfo: memFree=963408/1022884 swapFree=0/0
[pid=26200] ppid=26199 vsize=3152 CPUtime=0
/proc/26200/stat : 26200 (runsolver) R 26199 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29781496 3227648 33 18446744073709551615 134512640 134586868 4294404416 4294402464 4151395376 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/26200/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.139543 s]
/proc/loadavg: 1.07 1.08 1.07 2/55 26200
/proc/meminfo: memFree=963408/1022884 swapFree=0/0
[pid=26200] ppid=26199 vsize=25980 CPUtime=0
/proc/26200/stat : 26200 (aptitude) D 26199 26200 17863 34816 17863 4202496 149 0 11 0 0 0 0 0 20 0 1 0 29781496 26603520 73 18446744073709551615 140071656177664 140071660485016 140734178741184 140734178737848 140071654036246 0 0 0 0 0 0 0 17 0 0 0 13 0 0
/proc/26200/statm: 6495 73 48 1052 0 32 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 25980

[startup+0.200378 s]
/proc/loadavg: 1.07 1.08 1.07 2/55 26200
/proc/meminfo: memFree=963408/1022884 swapFree=0/0
[pid=26200] ppid=26199 vsize=36128 CPUtime=0
/proc/26200/stat : 26200 (aptitude) D 26199 26200 17863 34816 17863 4202496 166 0 16 0 0 0 0 0 20 0 1 0 29781496 36995072 92 18446744073709551615 140071656177664 140071660485016 140734178741184 140734178737608 140071654036870 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/26200/statm: 9032 92 58 1052 0 39 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 36128

[startup+0.300399 s]
/proc/loadavg: 1.07 1.08 1.07 2/55 26200
/proc/meminfo: memFree=963408/1022884 swapFree=0/0
[pid=26200] ppid=26199 vsize=54856 CPUtime=0
/proc/26200/stat : 26200 (aptitude) D 26199 26200 17863 34816 17863 4202496 276 0 26 0 0 0 0 0 20 0 1 0 29781496 56172544 204 18446744073709551615 140071656177664 140071660485016 140734178741184 140734178740392 140071653980045 0 0 0 0 0 0 0 17 0 0 0 28 0 0
/proc/26200/statm: 13714 204 142 1052 0 72 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54856

[startup+0.700246 s]
/proc/loadavg: 1.07 1.08 1.07 2/55 26200
/proc/meminfo: memFree=963408/1022884 swapFree=0/0
[pid=26200] ppid=26199 vsize=103288 CPUtime=0.03
/proc/26200/stat : 26200 (aptitude) D 26199 26200 17863 34816 17863 4202496 2534 1704 59 4 0 2 1 0 20 0 1 0 29781496 105766912 2395 18446744073709551615 140071656177664 140071660485016 140734178741184 140734178732656 140071651227546 0 134217728 4096 0 0 0 0 17 0 0 0 64 0 0
/proc/26200/statm: 25822 2395 1183 1052 0 1159 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 103288

[startup+1.5002 s]
/proc/loadavg: 1.07 1.08 1.07 1/56 26204
/proc/meminfo: memFree=953968/1022884 swapFree=0/0
[pid=26200] ppid=26199 vsize=103288 CPUtime=0.04
/proc/26200/stat : 26200 (aptitude) R 26199 26200 17863 34816 17863 4202496 6278 1704 186 4 0 3 1 0 20 0 1 0 29781496 105766912 6266 18446744073709551615 140071656177664 140071660485016 140734178741184 140734178732656 140071651035622 0 134217728 4096 0 0 0 0 17 0 0 0 142 0 0
/proc/26200/statm: 25822 6266 5054 1052 0 1159 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 103288

[startup+3.1003 s]
/proc/loadavg: 1.07 1.08 1.07 1/56 26204
/proc/meminfo: memFree=951612/1022884 swapFree=0/0
[pid=26200] ppid=26199 vsize=123068 CPUtime=0.69
/proc/26200/stat : 26200 (aptitude) D 26199 26200 17863 34816 17863 4202496 17423 1704 262 4 54 14 1 0 20 0 1 0 29781496 126021632 15963 18446744073709551615 140071656177664 140071660485016 140734178741184 140734178730616 140071624933744 0 134217728 4096 0 0 0 0 17 0 0 0 238 0 0
/proc/26200/statm: 30767 15963 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 123068
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.06 1.08 1.07 2/57 26206
/proc/meminfo: memFree=804788/1022884 swapFree=0/0
[pid=26200] ppid=26199 vsize=139296 CPUtime=3.52
/proc/26200/stat : 26200 (aptitude) S 26199 26200 17863 34816 17863 4202496 22388 2201 262 6 328 23 1 0 20 0 2 0 29781496 142639104 18542 18446744073709551615 140071656177664 140071660485016 140734178741184 140734178732944 140071624922699 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 271 0 0
/proc/26200/statm: 34824 18542 10353 1052 0 10161 0
[pid=26200/tid=26205] ppid=26199 vsize=139296 CPUtime=0.03
/proc/26200/task/26205/stat : 26205 (aptitude) R 26199 26200 17863 34816 17863 4202560 621 2201 0 6 2 0 1 0 20 0 2 0 29781853 142639104 18542 18446744073709551615 140071656177664 140071660485016 140734178741184 140071543845992 140071659602480 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.52
Current children cumulated vsize (KiB) 139296
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.06 1.08 1.07 2/57 26206
/proc/meminfo: memFree=730140/1022884 swapFree=0/0
[pid=26200] ppid=26199 vsize=282248 CPUtime=9.88
/proc/26200/stat : 26200 (aptitude) S 26199 26200 17863 34816 17863 4202496 42265 2201 262 6 956 31 1 0 20 0 2 0 29781496 289021952 37903 18446744073709551615 140071656177664 140071660485016 140734178741184 140734178732944 140071624922699 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 271 0 0
/proc/26200/statm: 70562 37903 10359 1052 0 45899 0
[pid=26200/tid=26205] ppid=26199 vsize=282248 CPUtime=6.4
/proc/26200/task/26205/stat : 26205 (aptitude) R 26199 26200 17863 34816 17863 4202560 20496 2201 0 6 630 9 1 0 20 0 2 0 29781853 289021952 37903 18446744073709551615 140071656177664 140071660485016 140734178741184 140071543848760 140071651001668 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.88
Current children cumulated vsize (KiB) 282248
heavy processes:

[startup+25.5003 s]
/proc/loadavg: 1.05 1.07 1.06 2/57 26206
/proc/meminfo: memFree=631312/1022884 swapFree=0/0
[pid=26200] ppid=26199 vsize=377488 CPUtime=22.62
/proc/26200/stat : 26200 (aptitude) S 26199 26200 17863 34816 17863 4202496 66098 2201 262 6 2219 42 1 0 20 0 2 0 29781496 386547712 61674 18446744073709551615 140071656177664 140071660485016 140734178741184 140734178732944 140071624922699 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 271 0 0
/proc/26200/statm: 94372 61674 10359 1052 0 69709 0
[pid=26200/tid=26205] ppid=26199 vsize=377488 CPUtime=19.13
/proc/26200/task/26205/stat : 26205 (aptitude) R 26199 26200 17863 34816 17863 4202560 44329 2201 0 6 1892 20 1 0 20 0 2 0 29781853 386547712 61674 18446744073709551615 140071656177664 140071660485016 140734178741184 140071543846424 140071658823979 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.62
Current children cumulated vsize (KiB) 377488

[startup+51.1003 s]
/proc/loadavg: 1.03 1.06 1.06 2/57 26206
/proc/meminfo: memFree=462300/1022884 swapFree=0/0
[pid=26200] ppid=26199 vsize=547900 CPUtime=48.08
/proc/26200/stat : 26200 (aptitude) S 26199 26200 17863 34816 17863 4202496 108997 2201 262 6 4741 66 1 0 20 0 2 0 29781496 561049600 104215 18446744073709551615 140071656177664 140071660485016 140734178741184 140734178732944 140071624922699 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 271 0 0
/proc/26200/statm: 136975 104215 10374 1052 0 112312 0
[pid=26200/tid=26205] ppid=26199 vsize=547900 CPUtime=44.59
/proc/26200/task/26205/stat : 26205 (aptitude) R 26199 26200 17863 34816 17863 4202560 87222 2201 0 6 4414 44 1 0 20 0 2 0 29781853 561049600 104215 18446744073709551615 140071656177664 140071660485016 140734178741184 140071543846424 140071613678467 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 48.08
Current children cumulated vsize (KiB) 547900

[startup+102.3 s]
/proc/loadavg: 1.01 1.05 1.06 2/57 26206
/proc/meminfo: memFree=194584/1022884 swapFree=0/0
[pid=26200] ppid=26199 vsize=811888 CPUtime=99.02
/proc/26200/stat : 26200 (aptitude) S 26199 26200 17863 34816 17863 4202496 175538 2201 262 6 9801 100 1 0 20 0 2 0 29781496 831373312 170259 18446744073709551615 140071656177664 140071660485016 140734178741184 140734178732944 140071624922699 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 271 0 0
/proc/26200/statm: 202972 170259 10374 1052 0 178309 0
[pid=26200/tid=26205] ppid=26199 vsize=811888 CPUtime=95.53
/proc/26200/task/26205/stat : 26205 (aptitude) R 26199 26200 17863 34816 17863 4202560 153763 2201 0 6 9474 78 1 0 20 0 2 0 29781853 831373312 170259 18446744073709551615 140071656177664 140071660485016 140734178741184 140071543848632 140071658802335 0 134217728 4096 0 0 0 0 -1 0 0 0 4 0 0
Current children cumulated CPU time (s) 99.02
Current children cumulated vsize (KiB) 811888

[startup+162.3 s]
/proc/loadavg: 1.29 1.11 1.07 1/57 26206
/proc/meminfo: memFree=9316/1022884 swapFree=0/0
[pid=26200] ppid=26199 vsize=1148444 CPUtime=157.07
/proc/26200/stat : 26200 (aptitude) S 26199 26200 17863 34816 17863 4202496 259712 2201 340 6 15564 142 1 0 20 0 2 0 29781496 1176006656 244143 18446744073709551615 140071656177664 140071660485016 140734178741184 140734178732944 140071624922699 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 271 0 0
/proc/26200/statm: 287111 244143 10061 1052 0 262448 0
[pid=26200/tid=26205] ppid=26199 vsize=1148444 CPUtime=153.57
/proc/26200/task/26205/stat : 26205 (aptitude) D 26199 26200 17863 34816 17863 4202560 237937 2201 78 6 15236 120 1 0 20 0 2 0 29781853 1176006656 244143 18446744073709551615 140071656177664 140071660485016 140734178741184 140071543846552 140071614330063 0 134217728 4096 0 0 0 0 -1 0 0 0 132 0 0
Current children cumulated CPU time (s) 157.07
Current children cumulated vsize (KiB) 1148444



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+163.203 s]
/proc/loadavg: 1.29 1.11 1.07 1/57 26206
/proc/meminfo: memFree=9576/1022884 swapFree=0/0
[pid=26200] ppid=26199 vsize=1151092 CPUtime=157.56
/proc/26200/stat : 26200 (aptitude) S 26199 26200 17863 34816 17863 4202496 260440 2201 404 6 15613 142 1 0 20 0 2 0 29781496 1178718208 244159 18446744073709551615 140071656177664 140071660485016 140734178741184 140734178732944 140071624922699 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 271 0 0
/proc/26200/statm: 287773 244159 9983 1052 0 263110 0
[pid=26200/tid=26205] ppid=26199 vsize=1151092 CPUtime=154.06
/proc/26200/task/26205/stat : 26205 (aptitude) D 26199 26200 17863 34816 17863 4202560 238665 2201 142 6 15285 120 1 0 20 0 2 0 29781853 1178718208 244159 18446744073709551615 140071656177664 140071660485016 140734178741184 140071543848792 140071658793852 0 134217728 4096 0 0 0 0 -1 0 0 0 171 0 0
Current children cumulated CPU time (s) 157.56
Current children cumulated vsize (KiB) 1151092

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): 163.3
CPU time (s): 157.662
CPU user time (s): 156.17
CPU system time (s): 1.49209
CPU usage (%): 96.5474
Max. virtual memory (cumulated for all children) (KiB): 1151092

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 156.17
system time used= 1.49209
maximum resident set size= 980472
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262652
page faults= 411
swaps= 0
block input operations= 262360
block output operations= 104
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2906
involuntary context switches= 3340

runsolver used 0.264016 second user time and 0.500031 second system time

The end