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/67.runsolver.aptitude aptitude -s -y --without-recommends install xpenguins pocketpc-binutils cdparanoia sane-utils pmccabe 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.38 1.14 1.06 2/56 25957 /proc/meminfo: memFree=874036/1022884 swapFree=0/0 [pid=25957] ppid=25956 vsize=3152 CPUtime=0 /proc/25957/stat : 25957 (runsolver) R 25956 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29662457 3227648 33 18446744073709551615 134512640 134586868 4292691536 4292689584 4151981104 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/25957/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.16419 s] /proc/loadavg: 1.38 1.14 1.06 2/56 25957 /proc/meminfo: memFree=874036/1022884 swapFree=0/0 [pid=25957] ppid=25956 vsize=54968 CPUtime=0.01 /proc/25957/stat : 25957 (aptitude) D 25956 25957 17863 34816 17863 4202496 1085 0 13 0 1 0 0 0 20 0 1 0 29662457 56287232 988 18446744073709551615 140539819335680 140539823643032 140735790220256 140735790215416 140539788091760 0 134217728 4096 0 0 0 0 17 0 0 0 14 0 0 /proc/25957/statm: 13742 988 824 1052 0 106 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 54968 [startup+0.20028 s] /proc/loadavg: 1.38 1.14 1.06 2/56 25957 /proc/meminfo: memFree=874036/1022884 swapFree=0/0 [pid=25957] ppid=25956 vsize=103288 CPUtime=0.03 /proc/25957/stat : 25957 (aptitude) R 25956 25957 17863 34816 17863 4202496 6843 1707 13 0 1 1 1 0 20 0 1 0 29662457 105766912 6654 18446744073709551615 140539819335680 140539823643032 140735790220256 140735790211728 140539814183192 0 134217728 4096 0 0 0 0 17 0 0 0 16 0 0 /proc/25957/statm: 25822 6654 5442 1052 0 1159 0 Current children cumulated CPU time (s) 0.03 Current children cumulated vsize (KiB) 103288 [startup+0.30026 s] /proc/loadavg: 1.38 1.14 1.06 2/56 25957 /proc/meminfo: memFree=874036/1022884 swapFree=0/0 [pid=25957] ppid=25956 vsize=103288 CPUtime=0.13 /proc/25957/stat : 25957 (aptitude) R 25956 25957 17863 34816 17863 4202496 11235 1707 13 0 10 2 1 0 20 0 1 0 29662457 105766912 11046 18446744073709551615 140539819335680 140539823643032 140735790220256 140735790211520 140539814176232 0 134217728 4096 0 0 0 0 17 0 0 0 16 0 0 /proc/25957/statm: 25822 11046 9834 1052 0 1159 0 Current children cumulated CPU time (s) 0.13 Current children cumulated vsize (KiB) 103288 [startup+0.700221 s] /proc/loadavg: 1.38 1.14 1.06 2/56 25957 /proc/meminfo: memFree=874036/1022884 swapFree=0/0 [pid=25957] ppid=25956 vsize=123068 CPUtime=0.47 /proc/25957/stat : 25957 (aptitude) D 25956 25957 17863 34816 17863 4202496 17647 1707 13 0 42 4 1 0 20 0 1 0 29662457 126021632 15934 18446744073709551615 140539819335680 140539823643032 140735790220256 140735790209688 140539788091760 0 134217728 4096 0 0 0 0 17 0 0 0 17 0 0 /proc/25957/statm: 30767 15934 9973 1052 0 6104 0 Current children cumulated CPU time (s) 0.47 Current children cumulated vsize (KiB) 123068 [startup+1.50031 s] /proc/loadavg: 1.38 1.14 1.06 2/56 25963 /proc/meminfo: memFree=823076/1022884 swapFree=0/0 [pid=25957] ppid=25956 vsize=123068 CPUtime=0.63 /proc/25957/stat : 25957 (aptitude) D 25956 25957 17863 34816 17863 4202496 17674 1707 13 0 53 9 1 0 20 0 1 0 29662457 126021632 15961 18446744073709551615 140539819335680 140539823643032 140735790220256 140735790209688 140539788091760 0 134217728 4096 0 0 0 0 17 0 0 0 79 0 0 /proc/25957/statm: 30767 15961 9976 1052 0 6104 0 Current children cumulated CPU time (s) 0.63 Current children cumulated vsize (KiB) 123068 [startup+3.10024 s] /proc/loadavg: 1.38 1.14 1.06 2/57 25964 /proc/meminfo: memFree=737132/1022884 swapFree=0/0 [pid=25957] ppid=25956 vsize=135972 CPUtime=1.68 /proc/25957/stat : 25957 (aptitude) R 25956 25957 17863 34816 17863 4202496 20670 1707 13 0 150 17 1 0 20 0 2 0 29662457 139235328 17598 18446744073709551615 140539819335680 140539823643032 140735790220256 140735790207416 140539788076568 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 122 0 0 /proc/25957/statm: 33993 17598 10244 1052 0 9330 0 [pid=25957/tid=25964] ppid=25956 vsize=135972 CPUtime=0.01 /proc/25957/task/25964/stat : 25964 (aptitude) S 25956 25957 17863 34816 17863 4202560 4 1707 0 0 0 0 1 0 20 0 2 0 29662669 139235328 17598 18446744073709551615 140539819335680 140539823643032 140735790220256 140539707013120 140539788079828 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 1.68 Current children cumulated vsize (KiB) 135972 heavy processes: [startup+6.30024 s] /proc/loadavg: 1.43 1.16 1.07 3/57 26020 /proc/meminfo: memFree=714068/1022884 swapFree=0/0 [pid=25957] ppid=25956 vsize=149336 CPUtime=3.64 /proc/25957/stat : 25957 (aptitude) R 25956 25957 17863 34816 17863 4202496 26750 2205 13 0 343 20 1 0 20 0 2 0 29662457 152920064 21101 18446744073709551615 140539819335680 140539823643032 140735790220256 140735790210344 140539814178940 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 122 0 0 /proc/25957/statm: 37334 21101 10402 1052 0 12664 0 [pid=25957/tid=25964] ppid=25956 vsize=149336 CPUtime=0.6 /proc/25957/task/25964/stat : 25964 (aptitude) S 25956 25957 17863 34816 17863 4202560 4454 2205 0 0 58 1 1 0 20 0 2 0 29662669 152920064 21101 18446744073709551615 140539819335680 140539823643032 140735790220256 140539707013120 140539788079828 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.64 Current children cumulated vsize (KiB) 149336 heavy processes: %CPU=26 pid=26041 uid=0 cmd=/bin/sh /etc/puppet/etckeeper-commit-post Solver just ended. Dumping a history of the last processes samples [startup+6.40348 s] /proc/loadavg: 1.43 1.16 1.07 3/59 26042 /proc/meminfo: memFree=706248/1022884 swapFree=0/0 [pid=25957] ppid=25956 vsize=149336 CPUtime=3.69 /proc/25957/stat : 25957 (aptitude) R 25956 25957 17863 34816 17863 4202496 27026 2205 13 0 348 20 1 0 20 0 2 0 29662457 152920064 21101 18446744073709551615 140539819335680 140539823643032 140735790220256 140735790208120 140539814190316 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 122 0 0 /proc/25957/statm: 37334 21101 10402 1052 0 12664 0 [pid=25957/tid=25964] ppid=25956 vsize=149336 CPUtime=0.6 /proc/25957/task/25964/stat : 25964 (aptitude) S 25956 25957 17863 34816 17863 4202560 4454 2205 0 0 58 1 1 0 20 0 2 0 29662669 152920064 21101 18446744073709551615 140539819335680 140539823643032 140735790220256 140539707013120 140539788079828 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.69 Current children cumulated vsize (KiB) 149336 [startup+6.60025 s] /proc/loadavg: 1.43 1.16 1.07 2/58 26044 /proc/meminfo: memFree=706240/1022884 swapFree=0/0 [pid=25957] ppid=25956 vsize=149336 CPUtime=3.84 /proc/25957/stat : 25957 (aptitude) R 25956 25957 17863 34816 17863 4202496 28743 2205 13 0 362 21 1 0 20 0 2 0 29662457 152920064 21101 18446744073709551615 140539819335680 140539823643032 140735790220256 140735790212328 140539814233400 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 122 0 0 /proc/25957/statm: 37334 21101 10402 1052 0 12664 0 [pid=25957/tid=25964] ppid=25956 vsize=149336 CPUtime=0.6 /proc/25957/task/25964/stat : 25964 (aptitude) S 25956 25957 17863 34816 17863 4202560 4454 2205 0 0 58 1 1 0 20 0 2 0 29662669 152920064 21101 18446744073709551615 140539819335680 140539823643032 140735790220256 140539707013120 140539788079828 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.84 Current children cumulated vsize (KiB) 149336 [startup+6.70313 s] /proc/loadavg: 1.43 1.16 1.07 2/58 26044 /proc/meminfo: memFree=706240/1022884 swapFree=0/0 [pid=25957] ppid=25956 vsize=98716 CPUtime=3.89 /proc/25957/stat : 25957 (aptitude) R 25956 25957 17863 34816 17863 4202496 28917 2707 13 0 365 23 1 0 20 0 1 0 29662457 101085184 5399 18446744073709551615 140539819335680 140539823643032 140735790220256 140735790219816 140539777201642 0 134217728 4096 0 0 0 0 17 0 0 0 122 0 0 /proc/25957/statm: 24679 5399 1501 1052 0 8935 0 Current children cumulated CPU time (s) 3.89 Current children cumulated vsize (KiB) 98716 Child status: 0 Real time (s): 6.70756 CPU time (s): 3.91224 CPU user time (s): 3.66823 CPU system time (s): 0.244015 CPU usage (%): 58.3259 Max. virtual memory (cumulated for all children) (KiB): 149336 getrusage(RUSAGE_CHILDREN,...) data: user time used= 3.66823 system time used= 0.244015 maximum resident set size= 84416 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 31691 page faults= 13 swaps= 0 block input operations= 215504 block output operations= 8 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 2201 involuntary context switches= 1048 runsolver used 0 second user time and 0.044002 second system time The end