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/logs/11.runsolver.aptitude aptitude -s -y --without-recommends install vcheck libsp-gxmlcpp1 ldapvi python-pyxine nwall 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.19 1.11 1.03 2/55 22992 /proc/meminfo: memFree=810168/1022884 swapFree=0/0 [pid=22992] ppid=22991 vsize=3152 CPUtime=0 /proc/22992/stat : 22992 (runsolver) R 22991 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28764330 3227648 33 18446744073709551615 134512640 134586868 4290982592 4290980640 4151403568 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/22992/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.173885 s] /proc/loadavg: 1.19 1.11 1.03 2/55 22992 /proc/meminfo: memFree=810168/1022884 swapFree=0/0 [pid=22992] ppid=22991 vsize=100508 CPUtime=0.17 /proc/22992/stat : 22992 (aptitude) R 22991 22992 17863 34816 17863 4202496 10600 1707 0 0 14 2 1 0 20 0 1 0 28764330 102920192 10400 18446744073709551615 139968792039424 139968796346776 140733243709264 140733243700528 139968786883025 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/22992/statm: 25127 10400 9225 1052 0 1122 0 Current children cumulated CPU time (s) 0.17 Current children cumulated vsize (KiB) 100508 [startup+0.200287 s] /proc/loadavg: 1.19 1.11 1.03 2/55 22992 /proc/meminfo: memFree=810168/1022884 swapFree=0/0 [pid=22992] ppid=22991 vsize=100508 CPUtime=0.2 /proc/22992/stat : 22992 (aptitude) R 22991 22992 17863 34816 17863 4202496 10607 1707 0 0 17 2 1 0 20 0 1 0 28764330 102920192 10407 18446744073709551615 139968792039424 139968796346776 140733243709264 140733243700528 139968786884049 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/22992/statm: 25127 10407 9232 1052 0 1122 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 100508 [startup+0.300336 s] /proc/loadavg: 1.19 1.11 1.03 2/55 22992 /proc/meminfo: memFree=810168/1022884 swapFree=0/0 [pid=22992] ppid=22991 vsize=111108 CPUtime=0.29 /proc/22992/stat : 22992 (aptitude) R 22991 22992 17863 34816 17863 4202496 13342 1707 0 0 26 2 1 0 20 0 1 0 28764330 113774592 13134 18446744073709551615 139968792039424 139968796346776 140733243709264 140733243700856 139968794170616 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/22992/statm: 27777 13134 9302 1052 0 3772 0 Current children cumulated CPU time (s) 0.29 Current children cumulated vsize (KiB) 111108 [startup+0.700208 s] /proc/loadavg: 1.19 1.11 1.03 2/55 22992 /proc/meminfo: memFree=810168/1022884 swapFree=0/0 [pid=22992] ppid=22991 vsize=123288 CPUtime=0.69 /proc/22992/stat : 22992 (aptitude) R 22991 22992 17863 34816 17863 4202496 17029 1707 0 0 62 6 1 0 20 0 2 0 28764330 126246912 14303 18446744073709551615 139968792039424 139968796346776 140733243709264 140733243705048 139968786882776 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22992/statm: 30822 14303 9482 1052 0 6817 0 Current children cumulated CPU time (s) 0.69 Current children cumulated vsize (KiB) 123288 [startup+1.50031 s] /proc/loadavg: 1.19 1.11 1.03 2/57 22997 /proc/meminfo: memFree=782012/1022884 swapFree=0/0 [pid=22992] ppid=22991 vsize=132412 CPUtime=1.49 /proc/22992/stat : 22992 (aptitude) R 22991 22992 17863 34816 17863 4202496 19433 1707 0 0 140 8 1 0 20 0 2 0 28764330 135589888 16703 18446744073709551615 139968792039424 139968796346776 140733243709264 140733243699616 139968749549901 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22992/statm: 33103 16703 9585 1052 0 9098 0 [pid=22992/tid=22997] ppid=22991 vsize=132412 CPUtime=0.01 /proc/22992/task/22997/stat : 22997 (aptitude) S 22991 22992 17863 34816 17863 4202560 4 1707 0 0 0 0 1 0 20 0 2 0 28764394 135589888 16703 18446744073709551615 139968792039424 139968796346776 140733243709264 139968682866688 139968760783572 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 1.49 Current children cumulated vsize (KiB) 132412 [startup+3.10029 s] /proc/loadavg: 1.17 1.10 1.03 2/57 22998 /proc/meminfo: memFree=780888/1022884 swapFree=0/0 [pid=22992] ppid=22991 vsize=133784 CPUtime=3.07 /proc/22992/stat : 22992 (aptitude) R 22991 22992 17863 34816 17863 4202496 20572 2210 0 0 294 12 1 0 20 0 2 0 28764330 136994816 16935 18446744073709551615 139968792039424 139968796346776 140733243709264 140733243696080 139968749549920 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22992/statm: 33446 16935 9644 1052 0 9441 0 [pid=22992/tid=22997] ppid=22991 vsize=133784 CPUtime=0.01 /proc/22992/task/22997/stat : 22997 (aptitude) S 22991 22992 17863 34816 17863 4202560 6 2210 0 0 0 0 1 0 20 0 2 0 28764394 136994816 16935 18446744073709551615 139968792039424 139968796346776 140733243709264 139968682866688 139968760783572 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) 133784 [startup+6.30031 s] /proc/loadavg: 1.17 1.10 1.03 2/57 22998 /proc/meminfo: memFree=737620/1022884 swapFree=0/0 [pid=22992] ppid=22991 vsize=245124 CPUtime=6.25 /proc/22992/stat : 22992 (aptitude) S 22991 22992 17863 34816 17863 4202496 33030 2210 0 0 606 18 1 0 20 0 2 0 28764330 251006976 28625 18446744073709551615 139968792039424 139968796346776 140733243709264 140733243701024 139968760784459 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22992/statm: 61281 28625 9700 1052 0 37276 0 [pid=22992/tid=22997] ppid=22991 vsize=245124 CPUtime=3.17 /proc/22992/task/22997/stat : 22997 (aptitude) R 22991 22992 17863 34816 17863 4202560 12457 2210 0 0 310 6 1 0 20 0 2 0 28764394 251006976 28625 18446744073709551615 139968792039424 139968796346776 140733243709264 139968682858008 139968760775089 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 6.25 Current children cumulated vsize (KiB) 245124 Solver just ended. Dumping a history of the last processes samples [startup+6.40037 s] /proc/loadavg: 1.17 1.10 1.03 2/57 22998 /proc/meminfo: memFree=737620/1022884 swapFree=0/0 [pid=22992] ppid=22991 vsize=245784 CPUtime=6.35 /proc/22992/stat : 22992 (aptitude) S 22991 22992 17863 34816 17863 4202496 33176 2210 0 0 616 18 1 0 20 0 2 0 28764330 251682816 28771 18446744073709551615 139968792039424 139968796346776 140733243709264 140733243701024 139968760784459 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22992/statm: 61446 28771 9700 1052 0 37441 0 [pid=22992/tid=22997] ppid=22991 vsize=245784 CPUtime=3.27 /proc/22992/task/22997/stat : 22997 (aptitude) R 22991 22992 17863 34816 17863 4202560 12603 2210 0 0 320 6 1 0 20 0 2 0 28764394 251682816 28771 18446744073709551615 139968792039424 139968796346776 140733243709264 139968682858056 139968794740709 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 6.35 Current children cumulated vsize (KiB) 245784 [startup+9.60031 s] /proc/loadavg: 1.16 1.10 1.03 2/57 22998 /proc/meminfo: memFree=721252/1022884 swapFree=0/0 [pid=22992] ppid=22991 vsize=266152 CPUtime=9.54 /proc/22992/stat : 22992 (aptitude) S 22991 22992 17863 34816 17863 4202496 38412 2210 0 0 933 20 1 0 20 0 2 0 28764330 272539648 33878 18446744073709551615 139968792039424 139968796346776 140733243709264 140733243701024 139968760784459 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22992/statm: 66538 33878 9700 1052 0 42533 0 [pid=22992/tid=22997] ppid=22991 vsize=266152 CPUtime=6.46 /proc/22992/task/22997/stat : 22997 (aptitude) R 22991 22992 17863 34816 17863 4202560 17839 2210 0 0 637 8 1 0 20 0 2 0 28764394 272539648 33878 18446744073709551615 139968792039424 139968796346776 140733243709264 139968682858008 139968794601532 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 9.54 Current children cumulated vsize (KiB) 266152 [startup+10.4003 s] /proc/loadavg: 1.16 1.10 1.03 2/57 22998 /proc/meminfo: memFree=710216/1022884 swapFree=0/0 [pid=22992] ppid=22991 vsize=273148 CPUtime=10.34 /proc/22992/stat : 22992 (aptitude) S 22991 22992 17863 34816 17863 4202496 40165 2210 0 0 1012 21 1 0 20 0 2 0 28764330 279703552 35608 18446744073709551615 139968792039424 139968796346776 140733243709264 140733243701024 139968760784459 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22992/statm: 68287 35608 9700 1052 0 44282 0 [pid=22992/tid=22997] ppid=22991 vsize=273148 CPUtime=7.26 /proc/22992/task/22997/stat : 22997 (aptitude) R 22991 22992 17863 34816 17863 4202560 19592 2210 0 0 716 9 1 0 20 0 2 0 28764394 279703552 35608 18446744073709551615 139968792039424 139968796346776 140733243709264 139968682858008 139968786867260 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 10.34 Current children cumulated vsize (KiB) 273148 [startup+11.2002 s] /proc/loadavg: 1.16 1.10 1.03 2/57 22998 /proc/meminfo: memFree=701908/1022884 swapFree=0/0 [pid=22992] ppid=22991 vsize=276636 CPUtime=11.13 /proc/22992/stat : 22992 (aptitude) R 22991 22992 17863 34816 17863 4202496 43701 2210 0 0 1090 22 1 0 20 0 2 0 28764330 283275264 36645 18446744073709551615 139968792039424 139968796346776 140733243709264 140733243697128 139968793874086 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22992/statm: 69159 36645 9749 1052 0 45147 0 [pid=22992/tid=22997] ppid=22991 vsize=276636 CPUtime=7.73 /proc/22992/task/22997/stat : 22997 (aptitude) S 22991 22992 17863 34816 17863 4202560 20452 2210 0 0 763 9 1 0 20 0 2 0 28764394 283275264 36645 18446744073709551615 139968792039424 139968796346776 140733243709264 139968682866688 139968760783572 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 11.13 Current children cumulated vsize (KiB) 276636 [startup+11.6014 s] /proc/loadavg: 1.16 1.10 1.03 2/57 22998 /proc/meminfo: memFree=701908/1022884 swapFree=0/0 [pid=22992] ppid=22991 vsize=180524 CPUtime=11.53 /proc/22992/stat : 22992 (aptitude) R 22991 22992 17863 34816 17863 4202496 44541 2711 0 0 1118 33 1 1 20 0 1 0 28764330 184856576 9522 18446744073709551615 139968792039424 139968796346776 140733243709264 140733243708824 139968749905386 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/22992/statm: 45131 9522 1507 1052 0 29387 0 Current children cumulated CPU time (s) 11.53 Current children cumulated vsize (KiB) 180524 Child status: 0 Real time (s): 11.6099 CPU time (s): 11.5567 CPU user time (s): 11.2007 CPU system time (s): 0.356022 CPU usage (%): 99.5418 Max. virtual memory (cumulated for all children) (KiB): 276636 getrusage(RUSAGE_CHILDREN,...) data: user time used= 11.2007 system time used= 0.356022 maximum resident set size= 147332 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 47319 page faults= 0 swaps= 0 block input operations= 0 block output operations= 136 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 78 involuntary context switches= 251 runsolver used 0.004 second user time and 0.060003 second system time The end