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/28.runsolver.aptitude aptitude -s -y --without-recommends install libpils-dev scigraphica wogerman bluez-pcmcia-support libperl4caml-ocaml-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.08 1.09 1.04 2/55 25222 /proc/meminfo: memFree=835200/1022884 swapFree=0/0 [pid=25222] ppid=25221 vsize=3152 CPUtime=0 /proc/25222/stat : 25222 (runsolver) R 25221 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29418727 3227648 33 18446744073709551615 134512640 134586868 4291829440 4291827488 4151878704 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/25222/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.170755 s] /proc/loadavg: 1.08 1.09 1.04 2/55 25222 /proc/meminfo: memFree=835200/1022884 swapFree=0/0 [pid=25222] ppid=25221 vsize=103288 CPUtime=0.15 /proc/25222/stat : 25222 (aptitude) R 25221 25222 17863 34816 17863 4202496 11289 1709 0 0 12 3 0 0 20 0 1 0 29418727 105766912 11091 18446744073709551615 140304026202112 140304030509464 140736417544320 140736417535584 140304021602341 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25222/statm: 25822 11091 9879 1052 0 1159 0 Current children cumulated CPU time (s) 0.15 Current children cumulated vsize (KiB) 103288 [startup+0.200323 s] /proc/loadavg: 1.08 1.09 1.04 2/55 25222 /proc/meminfo: memFree=835200/1022884 swapFree=0/0 [pid=25222] ppid=25221 vsize=103288 CPUtime=0.19 /proc/25222/stat : 25222 (aptitude) R 25221 25222 17863 34816 17863 4202496 11299 1709 0 0 16 3 0 0 20 0 1 0 29418727 105766912 11101 18446744073709551615 140304026202112 140304030509464 140736417544320 140736417535584 140304021043030 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25222/statm: 25822 11101 9889 1052 0 1159 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 103288 [startup+0.300229 s] /proc/loadavg: 1.08 1.09 1.04 2/55 25222 /proc/meminfo: memFree=835200/1022884 swapFree=0/0 [pid=25222] ppid=25221 vsize=103432 CPUtime=0.29 /proc/25222/stat : 25222 (aptitude) R 25221 25222 17863 34816 17863 4202496 11426 1709 0 0 26 3 0 0 20 0 1 0 29418727 105914368 11220 18446744073709551615 140304026202112 140304030509464 140736417544320 140736417534096 140304021055458 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25222/statm: 25858 11220 9956 1052 0 1195 0 Current children cumulated CPU time (s) 0.29 Current children cumulated vsize (KiB) 103432 [startup+0.700222 s] /proc/loadavg: 1.08 1.09 1.04 2/55 25222 /proc/meminfo: memFree=835200/1022884 swapFree=0/0 [pid=25222] ppid=25221 vsize=123068 CPUtime=0.68 /proc/25222/stat : 25222 (aptitude) R 25221 25222 17863 34816 17863 4202496 17687 1709 0 0 61 7 0 0 20 0 1 0 29418727 126021632 15965 18446744073709551615 140304026202112 140304030509464 140736417544320 140736417533752 140303983742495 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25222/statm: 30767 15965 9976 1052 0 6104 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 123068 [startup+1.50023 s] /proc/loadavg: 1.08 1.09 1.04 2/57 25227 /proc/meminfo: memFree=815212/1022884 swapFree=0/0 [pid=25222] ppid=25221 vsize=136084 CPUtime=1.48 /proc/25222/stat : 25222 (aptitude) R 25221 25222 17863 34816 17863 4202496 20649 1709 0 0 140 8 0 0 20 0 2 0 29418727 139350016 17569 18446744073709551615 140304026202112 140304030509464 140736417544320 140736417535592 140304028440807 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25222/statm: 34021 17569 10207 1052 0 9358 0 [pid=25222/tid=25227] ppid=25221 vsize=136084 CPUtime=0 /proc/25222/task/25227/stat : 25227 (aptitude) S 25221 25222 17863 34816 17863 4202560 4 1709 0 0 0 0 0 0 20 0 2 0 29418804 139350016 17569 18446744073709551615 140304026202112 140304030509464 140736417544320 140303913879552 140303994946260 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) 136084 [startup+3.10022 s] /proc/loadavg: 1.08 1.09 1.04 2/57 25227 /proc/meminfo: memFree=804920/1022884 swapFree=0/0 [pid=25222] ppid=25221 vsize=137852 CPUtime=3.06 /proc/25222/stat : 25222 (aptitude) R 25221 25222 17863 34816 17863 4202496 22033 2212 0 0 294 12 0 0 20 0 2 0 29418727 141160448 17944 18446744073709551615 140304026202112 140304030509464 140736417544320 140736417531024 140304028909564 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25222/statm: 34463 17944 10303 1052 0 9800 0 [pid=25222/tid=25227] ppid=25221 vsize=137852 CPUtime=0 /proc/25222/task/25227/stat : 25227 (aptitude) S 25221 25222 17863 34816 17863 4202560 6 2212 0 0 0 0 0 0 20 0 2 0 29418804 141160448 17944 18446744073709551615 140304026202112 140304030509464 140736417544320 140303913879552 140303994946260 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.06 Current children cumulated vsize (KiB) 137852 [startup+6.30022 s] /proc/loadavg: 1.07 1.09 1.04 2/57 25228 /proc/meminfo: memFree=770448/1022884 swapFree=0/0 [pid=25222] ppid=25221 vsize=247092 CPUtime=6.26 /proc/25222/stat : 25222 (aptitude) S 25221 25222 17863 34816 17863 4202496 33492 2212 0 0 610 16 0 0 20 0 2 0 29418727 253022208 29108 18446744073709551615 140304026202112 140304030509464 140736417544320 140736417536080 140303994947147 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25222/statm: 61773 29108 10359 1052 0 37110 0 [pid=25222/tid=25227] ppid=25221 vsize=247092 CPUtime=2.82 /proc/25222/task/25227/stat : 25227 (aptitude) R 25221 25222 17863 34816 17863 4202560 11457 2212 0 0 280 2 0 0 20 0 2 0 29418804 253022208 29108 18446744073709551615 140304026202112 140304030509464 140736417544320 140303913873080 140304028816472 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) 247092 [startup+12.7002 s] /proc/loadavg: 1.06 1.09 1.04 2/57 25228 /proc/meminfo: memFree=705720/1022884 swapFree=0/0 [pid=25222] ppid=25221 vsize=305788 CPUtime=12.63 /proc/25222/stat : 25222 (aptitude) S 25221 25222 17863 34816 17863 4202496 48431 2212 0 0 1240 23 0 0 20 0 2 0 29418727 313126912 43752 18446744073709551615 140304026202112 140304030509464 140736417544320 140736417536080 140303994947147 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25222/statm: 76447 43752 10359 1052 0 51784 0 [pid=25222/tid=25227] ppid=25221 vsize=305788 CPUtime=9.2 /proc/25222/task/25227/stat : 25227 (aptitude) R 25221 25222 17863 34816 17863 4202560 26396 2212 0 0 910 10 0 0 20 0 2 0 29418804 313126912 43752 18446744073709551615 140304026202112 140304030509464 140736417544320 140303913873080 140304028995041 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) 305788 [startup+25.5002 s] /proc/loadavg: 1.05 1.08 1.04 2/57 25228 /proc/meminfo: memFree=620532/1022884 swapFree=0/0 [pid=25222] ppid=25221 vsize=387372 CPUtime=25.36 /proc/25222/stat : 25222 (aptitude) S 25221 25222 17863 34816 17863 4202496 69034 2212 0 0 2501 35 0 0 20 0 2 0 29418727 396668928 64153 18446744073709551615 140304026202112 140304030509464 140736417544320 140736417536080 140303994947147 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25222/statm: 96843 64153 10360 1052 0 72180 0 [pid=25222/tid=25227] ppid=25221 vsize=387372 CPUtime=21.94 /proc/25222/task/25227/stat : 25227 (aptitude) R 25221 25222 17863 34816 17863 4202560 46999 2212 0 0 2172 22 0 0 20 0 2 0 29418804 396668928 64153 18446744073709551615 140304026202112 140304030509464 140736417544320 140303913873032 140304029031004 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 25.36 Current children cumulated vsize (KiB) 387372 [startup+51.1002 s] /proc/loadavg: 1.03 1.08 1.03 2/57 25228 /proc/meminfo: memFree=480908/1022884 swapFree=0/0 [pid=25222] ppid=25221 vsize=527936 CPUtime=50.83 /proc/25222/stat : 25222 (aptitude) S 25221 25222 17863 34816 17863 4202496 104746 2212 0 0 5030 53 0 0 20 0 2 0 29418727 540606464 99247 18446744073709551615 140304026202112 140304030509464 140736417544320 140736417536080 140303994947147 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25222/statm: 131984 99247 10374 1052 0 107321 0 [pid=25222/tid=25227] ppid=25221 vsize=527936 CPUtime=47.41 /proc/25222/task/25227/stat : 25227 (aptitude) R 25221 25222 17863 34816 17863 4202560 82705 2212 0 0 4701 40 0 0 20 0 2 0 29418804 540606464 99247 18446744073709551615 140304026202112 140304030509464 140736417544320 140303913872480 140304028826688 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 50.83 Current children cumulated vsize (KiB) 527936 [startup+102.3 s] /proc/loadavg: 1.01 1.06 1.03 2/57 25228 /proc/meminfo: memFree=216664/1022884 swapFree=0/0 [pid=25222] ppid=25221 vsize=789072 CPUtime=101.79 /proc/25222/stat : 25222 (aptitude) S 25221 25222 17863 34816 17863 4202496 170104 2212 0 0 10095 84 0 0 20 0 2 0 29418727 808009728 164546 18446744073709551615 140304026202112 140304030509464 140736417544320 140736417536080 140303994947147 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25222/statm: 197268 164546 10374 1052 0 172605 0 [pid=25222/tid=25227] ppid=25221 vsize=789072 CPUtime=98.37 /proc/25222/task/25227/stat : 25227 (aptitude) R 25221 25222 17863 34816 17863 4202560 148063 2212 0 0 9766 71 0 0 20 0 2 0 29418804 808009728 164546 18446744073709551615 140304026202112 140304030509464 140736417544320 140303913874136 140304028898403 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0 Current children cumulated CPU time (s) 101.79 Current children cumulated vsize (KiB) 789072 [startup+162.3 s] /proc/loadavg: 1.29 1.11 1.04 2/57 25228 /proc/meminfo: memFree=9896/1022884 swapFree=0/0 [pid=25222] ppid=25221 vsize=1077648 CPUtime=155.07 /proc/25222/stat : 25222 (aptitude) S 25221 25222 17863 34816 17863 4202496 246040 2212 811 0 15381 126 0 0 20 0 2 0 29418727 1103511552 232446 18446744073709551615 140304026202112 140304030509464 140736417544320 140736417536080 140303994947147 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25222/statm: 269412 232446 10087 1052 0 244749 0 [pid=25222/tid=25227] ppid=25221 vsize=1077648 CPUtime=151.62 /proc/25222/task/25227/stat : 25227 (aptitude) R 25221 25222 17863 34816 17863 4202560 223999 2212 811 0 15050 112 0 0 20 0 2 0 29418804 1103511552 232446 18446744073709551615 140304026202112 140304030509464 140736417544320 140303913871048 140304028900892 0 134217728 4096 0 0 0 0 -1 0 0 0 628 0 0 Current children cumulated CPU time (s) 155.07 Current children cumulated vsize (KiB) 1077648 Maximum VSize exceeded: sending signal-name then SIGKILL [startup+172.5 s] /proc/loadavg: 1.32 1.12 1.05 1/57 25228 /proc/meminfo: memFree=9380/1022884 swapFree=0/0 [pid=25222] ppid=25221 vsize=1151776 CPUtime=163.71 /proc/25222/stat : 25222 (aptitude) S 25221 25222 17863 34816 17863 4202496 264969 2212 1053 0 16231 140 0 0 20 0 2 0 29418727 1179418624 246868 18446744073709551615 140304026202112 140304030509464 140736417544320 140736417536080 140303994947147 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25222/statm: 287944 246868 9964 1052 0 263281 0 [pid=25222/tid=25227] ppid=25221 vsize=1151776 CPUtime=160.28 /proc/25222/task/25227/stat : 25227 (aptitude) R 25221 25222 17863 34816 17863 4202560 242920 2212 1049 0 15901 127 0 0 20 0 2 0 29418804 1179418624 246868 18446744073709551615 140304026202112 140304030509464 140736417544320 140303913872984 140304028797268 0 134217728 4096 0 0 0 0 -1 0 0 0 768 0 0 Current children cumulated CPU time (s) 163.71 Current children cumulated vsize (KiB) 1151776 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): 172.725 CPU time (s): 163.826 CPU user time (s): 162.338 CPU system time (s): 1.48809 CPU usage (%): 94.8479 Max. virtual memory (cumulated for all children) (KiB): 1151776 getrusage(RUSAGE_CHILDREN,...) data: user time used= 162.338 system time used= 1.48809 maximum resident set size= 987804 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 267201 page faults= 1062 swaps= 0 block input operations= 52640 block output operations= 168 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 1565 involuntary context switches= 3398 runsolver used 0 second user time and 0.792049 second system time The end