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/153.runsolver.aptitude aptitude -s -y --without-recommends remove libcomerr2 console-data libhal-storage0 keduca libreadline4 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.03 1.02 1.00 2/55 22579 /proc/meminfo: memFree=903216/1022884 swapFree=0/0 [pid=22579] ppid=22578 vsize=3152 CPUtime=0 /proc/22579/stat : 22579 (runsolver) R 22578 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28701453 3227648 32 18446744073709551615 134512640 134586868 4286840000 4286838048 4152095792 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/22579/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.113648 s] /proc/loadavg: 1.03 1.02 1.00 2/55 22579 /proc/meminfo: memFree=903216/1022884 swapFree=0/0 [pid=22579] ppid=22578 vsize=89152 CPUtime=0.1 /proc/22579/stat : 22579 (aptitude) R 22578 22579 17863 34816 17863 4202496 7765 1707 0 0 9 1 0 0 20 0 1 0 28701453 91291648 7563 18446744073709551615 140202297479168 140202301786520 140733209166960 140733209158224 140202292322534 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/22579/statm: 22288 7563 6653 1052 0 858 0 Current children cumulated CPU time (s) 0.1 Current children cumulated vsize (KiB) 89152 [startup+0.200304 s] /proc/loadavg: 1.03 1.02 1.00 2/55 22579 /proc/meminfo: memFree=903216/1022884 swapFree=0/0 [pid=22579] ppid=22578 vsize=89152 CPUtime=0.19 /proc/22579/stat : 22579 (aptitude) R 22578 22579 17863 34816 17863 4202496 7871 1707 0 0 18 1 0 0 20 0 1 0 28701453 91291648 7661 18446744073709551615 140202297479168 140202301786520 140733209166960 140733209156736 140202292327883 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/22579/statm: 22288 7661 6726 1052 0 858 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 89152 [startup+0.300275 s] /proc/loadavg: 1.03 1.02 1.00 2/55 22579 /proc/meminfo: memFree=903216/1022884 swapFree=0/0 [pid=22579] ppid=22578 vsize=101864 CPUtime=0.28 /proc/22579/stat : 22579 (aptitude) R 22578 22579 17863 34816 17863 4202496 11710 1707 0 0 26 2 0 0 20 0 1 0 28701453 104308736 10755 18446744073709551615 140202297479168 140202301786520 140733209166960 140733209156392 140202255019471 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/22579/statm: 25466 10755 6746 1052 0 4036 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 101864 [startup+0.700204 s] /proc/loadavg: 1.03 1.02 1.00 2/55 22579 /proc/meminfo: memFree=903216/1022884 swapFree=0/0 [pid=22579] ppid=22578 vsize=113868 CPUtime=0.68 /proc/22579/stat : 22579 (aptitude) R 22578 22579 17863 34816 17863 4202496 13632 1707 0 0 64 4 0 0 20 0 2 0 28701453 116600832 12002 18446744073709551615 140202297479168 140202301786520 140733209166960 140733209158232 140202254989570 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22579/statm: 28467 12002 6964 1052 0 7037 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 113868 [startup+1.50024 s] /proc/loadavg: 1.03 1.02 1.00 2/57 22584 /proc/meminfo: memFree=882748/1022884 swapFree=0/0 [pid=22579] ppid=22578 vsize=115240 CPUtime=1.47 /proc/22579/stat : 22579 (aptitude) R 22578 22579 17863 34816 17863 4202496 13835 1707 0 0 143 4 0 0 20 0 2 0 28701453 118005760 12204 18446744073709551615 140202297479168 140202301786520 140733209166960 140733209153664 140202254989448 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22579/statm: 28810 12204 7033 1052 0 7380 0 [pid=22579/tid=22584] ppid=22578 vsize=115240 CPUtime=0 /proc/22579/task/22584/stat : 22584 (aptitude) S 22578 22579 17863 34816 17863 4202560 4 1707 0 0 0 0 0 0 20 0 2 0 28701498 118005760 12204 18446744073709551615 140202297479168 140202301786520 140733209166960 140202200885248 140202266223316 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 1.47 Current children cumulated vsize (KiB) 115240 [startup+3.10024 s] /proc/loadavg: 1.03 1.02 1.00 2/57 22584 /proc/meminfo: memFree=860552/1022884 swapFree=0/0 [pid=22579] ppid=22578 vsize=148636 CPUtime=3.07 /proc/22579/stat : 22579 (aptitude) S 22578 22579 17863 34816 17863 4202496 22474 1707 0 0 298 9 0 0 20 0 2 0 28701453 152203264 20842 18446744073709551615 140202297479168 140202301786520 140733209166960 140733209158720 140202266224203 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22579/statm: 37159 20842 7090 1052 0 15729 0 [pid=22579/tid=22584] ppid=22578 vsize=148636 CPUtime=1.35 /proc/22579/task/22584/stat : 22584 (aptitude) R 22578 22579 17863 34816 17863 4202560 8638 1707 0 0 131 4 0 0 20 0 2 0 28701498 152203264 20842 18446744073709551615 140202297479168 140202301786520 140733209166960 140202200876136 140202299690074 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) 148636 [startup+6.30024 s] /proc/loadavg: 1.03 1.02 1.00 2/57 22584 /proc/meminfo: memFree=829056/1022884 swapFree=0/0 [pid=22579] ppid=22578 vsize=239144 CPUtime=6.26 /proc/22579/stat : 22579 (aptitude) S 22578 22579 17863 34816 17863 4202496 28723 1707 0 0 612 14 0 0 20 0 2 0 28701453 244883456 27091 18446744073709551615 140202297479168 140202301786520 140733209166960 140733209158720 140202266224203 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22579/statm: 59786 27091 7091 1052 0 38356 0 [pid=22579/tid=22584] ppid=22578 vsize=239144 CPUtime=4.54 /proc/22579/task/22584/stat : 22584 (aptitude) R 22578 22579 17863 34816 17863 4202560 14886 1707 0 0 445 9 0 0 20 0 2 0 28701498 244883456 27091 18446744073709551615 140202297479168 140202301786520 140733209166960 140202200875016 140202255631571 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) 239144 [startup+12.7002 s] /proc/loadavg: 1.11 1.04 1.01 2/57 22584 /proc/meminfo: memFree=770528/1022884 swapFree=0/0 [pid=22579] ppid=22578 vsize=296848 CPUtime=12.63 /proc/22579/stat : 22579 (aptitude) S 22578 22579 17863 34816 17863 4202496 43130 1707 0 0 1245 18 0 0 20 0 2 0 28701453 303972352 41498 18446744073709551615 140202297479168 140202301786520 140733209166960 140733209158720 140202266224203 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22579/statm: 74212 41498 7091 1052 0 52782 0 [pid=22579/tid=22584] ppid=22578 vsize=296848 CPUtime=10.91 /proc/22579/task/22584/stat : 22584 (aptitude) R 22578 22579 17863 34816 17863 4202560 29293 1707 0 0 1077 14 0 0 20 0 2 0 28701498 303972352 41498 18446744073709551615 140202297479168 140202301786520 140733209166960 140202200876568 140202292164576 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) 296848 [startup+25.5003 s] /proc/loadavg: 1.08 1.03 1.01 2/57 22584 /proc/meminfo: memFree=658300/1022884 swapFree=0/0 [pid=22579] ppid=22578 vsize=405720 CPUtime=25.35 /proc/22579/stat : 22579 (aptitude) S 22578 22579 17863 34816 17863 4202496 70311 1707 0 0 2504 31 0 0 20 0 2 0 28701453 415457280 68679 18446744073709551615 140202297479168 140202301786520 140733209166960 140733209158720 140202266224203 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22579/statm: 101430 68679 7092 1052 0 80000 0 [pid=22579/tid=22584] ppid=22578 vsize=405720 CPUtime=23.62 /proc/22579/task/22584/stat : 22584 (aptitude) R 22578 22579 17863 34816 17863 4202560 56474 1707 0 0 2336 26 0 0 20 0 2 0 28701498 415457280 68679 18446744073709551615 140202297479168 140202301786520 140733209166960 140202200876616 140202300281109 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 25.35 Current children cumulated vsize (KiB) 405720 [startup+51.1003 s] /proc/loadavg: 1.05 1.03 1.00 2/57 22584 /proc/meminfo: memFree=465356/1022884 swapFree=0/0 [pid=22579] ppid=22578 vsize=600004 CPUtime=50.83 /proc/22579/stat : 22579 (aptitude) S 22578 22579 17863 34816 17863 4202496 118841 1707 0 0 5025 58 0 0 20 0 2 0 28701453 614404096 117209 18446744073709551615 140202297479168 140202301786520 140733209166960 140733209158720 140202266224203 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22579/statm: 150001 117209 7092 1052 0 128571 0 [pid=22579/tid=22584] ppid=22578 vsize=600004 CPUtime=49.12 /proc/22579/task/22584/stat : 22584 (aptitude) R 22578 22579 17863 34816 17863 4202560 105004 1707 0 0 4858 54 0 0 20 0 2 0 28701498 614404096 117209 18446744073709551615 140202297479168 140202301786520 140733209166960 140202200876568 140202263412376 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) 600004 [startup+102.3 s] /proc/loadavg: 1.02 1.02 1.00 2/57 22584 /proc/meminfo: memFree=73516/1022884 swapFree=0/0 [pid=22579] ppid=22578 vsize=987396 CPUtime=101.79 /proc/22579/stat : 22579 (aptitude) S 22578 22579 17863 34816 17863 4202496 215642 1707 0 0 10065 114 0 0 20 0 2 0 28701453 1011093504 214010 18446744073709551615 140202297479168 140202301786520 140733209166960 140733209158720 140202266224203 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22579/statm: 246849 214010 7106 1052 0 225419 0 [pid=22579/tid=22584] ppid=22578 vsize=987396 CPUtime=100.06 /proc/22579/task/22584/stat : 22584 (aptitude) R 22578 22579 17863 34816 17863 4202560 201799 1707 0 0 9897 109 0 0 20 0 2 0 28701498 1011093504 214010 18446744073709551615 140202297479168 140202301786520 140733209166960 140202200879384 140202263795064 0 134217728 4096 0 0 0 0 -1 0 0 0 3 0 0 Current children cumulated CPU time (s) 101.79 Current children cumulated vsize (KiB) 987396 Maximum VSize exceeded: sending signal-name then SIGKILL [startup+126.803 s] /proc/loadavg: 1.08 1.04 1.00 2/57 22584 /proc/meminfo: memFree=10092/1022884 swapFree=0/0 [pid=22579] ppid=22578 vsize=1151340 CPUtime=124.08 /proc/22579/stat : 22579 (aptitude) S 22578 22579 17863 34816 17863 4202496 256806 1707 136 0 12273 135 0 0 20 0 2 0 28701453 1178972160 246582 18446744073709551615 140202297479168 140202301786520 140733209166960 140733209158720 140202266224203 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22579/statm: 287835 246582 6688 1052 0 266405 0 [pid=22579/tid=22584] ppid=22578 vsize=1151340 CPUtime=122.35 /proc/22579/task/22584/stat : 22584 (aptitude) R 22578 22579 17863 34816 17863 4202560 242963 1707 136 0 12105 130 0 0 20 0 2 0 28701498 1178972160 246582 18446744073709551615 140202297479168 140202301786520 140733209166960 140202200878776 140202299690074 0 134217728 4096 0 0 0 0 -1 0 0 0 174 0 0 Current children cumulated CPU time (s) 124.08 Current children cumulated vsize (KiB) 1151340 Sending Terminated to process tree (bottom up) Sleeping 2 seconds Solver just ended. Dumping a history of the last processes samples [startup+126.803 s] /proc/loadavg: 1.08 1.04 1.00 2/57 22584 /proc/meminfo: memFree=10092/1022884 swapFree=0/0 [pid=22579] ppid=22578 vsize=1151340 CPUtime=124.08 /proc/22579/stat : 22579 (aptitude) S 22578 22579 17863 34816 17863 4202496 256806 1707 136 0 12273 135 0 0 20 0 2 0 28701453 1178972160 246582 18446744073709551615 140202297479168 140202301786520 140733209166960 140733209158720 140202266224203 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22579/statm: 287835 246582 6688 1052 0 266405 0 [pid=22579/tid=22584] ppid=22578 vsize=1151340 CPUtime=122.35 /proc/22579/task/22584/stat : 22584 (aptitude) R 22578 22579 17863 34816 17863 4202560 242963 1707 136 0 12105 130 0 0 20 0 2 0 28701498 1178972160 246582 18446744073709551615 140202297479168 140202301786520 140733209166960 140202200878776 140202299690074 0 134217728 4096 0 0 0 0 -1 0 0 0 174 0 0 Current children cumulated CPU time (s) 124.08 Current children cumulated vsize (KiB) 1151340 Child ended because it received signal 15 (SIGTERM) Real time (s): 126.917 CPU time (s): 124.192 CPU user time (s): 122.768 CPU system time (s): 1.42409 CPU usage (%): 97.8524 Max. virtual memory (cumulated for all children) (KiB): 1151340 getrusage(RUSAGE_CHILDREN,...) data: user time used= 122.768 system time used= 1.42409 maximum resident set size= 988096 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 258553 page faults= 138 swaps= 0 block input operations= 7392 block output operations= 96 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 485 involuntary context switches= 2641 runsolver used 0.16001 second user time and 0.424026 second system time The end