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/46.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends install gtkguitune libwrap-ruby1.8 t1lib-bin tct libdb3-util 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: 0.99 0.97 0.97 2/55 4068 /proc/meminfo: memFree=582848/1022884 swapFree=0/0 [pid=4068] ppid=4067 vsize=3152 CPUtime=0 /proc/4068/stat : 4068 (runsolver) R 4067 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 30440841 3227648 33 18446744073709551615 134512640 134586868 4294296656 4294294704 4151895088 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/4068/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.112469 s] /proc/loadavg: 0.99 0.97 0.97 2/55 4068 /proc/meminfo: memFree=582848/1022884 swapFree=0/0 [pid=4068] ppid=4067 vsize=33244 CPUtime=0.13 /proc/4068/stat : 4068 (cupt) R 4067 4068 17872 34816 17872 4202496 1774 7221 0 0 4 2 5 2 20 0 1 0 30440841 34041856 1592 18446744073709551615 4194304 5184042 140735586634928 140735586632120 139654094655536 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4068/statm: 8311 1592 729 242 0 873 0 Current children cumulated CPU time (s) 0.13 Current children cumulated vsize (KiB) 33244 [startup+0.200301 s] /proc/loadavg: 0.99 0.97 0.97 2/55 4068 /proc/meminfo: memFree=582848/1022884 swapFree=0/0 [pid=4068] ppid=4067 vsize=35492 CPUtime=0.22 /proc/4068/stat : 4068 (cupt) R 4067 4068 17872 34816 17872 4202496 2350 7221 0 0 11 4 5 2 20 0 1 0 30440841 36343808 2167 18446744073709551615 4194304 5184042 140735586634928 140735586632120 139654094786638 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4068/statm: 8873 2167 729 242 0 1435 0 Current children cumulated CPU time (s) 0.22 Current children cumulated vsize (KiB) 35492 [startup+0.300301 s] /proc/loadavg: 0.99 0.97 0.97 2/55 4068 /proc/meminfo: memFree=582848/1022884 swapFree=0/0 [pid=4068] ppid=4067 vsize=37984 CPUtime=0.32 /proc/4068/stat : 4068 (cupt) R 4067 4068 17872 34816 17872 4202496 3051 7221 0 0 20 5 5 2 20 0 1 0 30440841 38895616 2805 18446744073709551615 4194304 5184042 140735586634928 140735586632120 139654094721363 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4068/statm: 9496 2805 739 242 0 2058 0 Current children cumulated CPU time (s) 0.32 Current children cumulated vsize (KiB) 37984 [startup+0.700203 s] /proc/loadavg: 0.99 0.97 0.97 2/55 4068 /proc/meminfo: memFree=582848/1022884 swapFree=0/0 [pid=4068] ppid=4067 vsize=64348 CPUtime=0.72 /proc/4068/stat : 4068 (cupt) R 4067 4068 17872 34816 17872 4202496 9741 7221 0 0 55 10 5 2 20 0 1 0 30440841 65892352 9486 18446744073709551615 4194304 5184042 140735586634928 140735586632120 139654111065534 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4068/statm: 16087 9486 851 242 0 8649 0 Current children cumulated CPU time (s) 0.72 Current children cumulated vsize (KiB) 64348 [startup+1.5002 s] /proc/loadavg: 0.99 0.97 0.97 2/56 4088 /proc/meminfo: memFree=546640/1022884 swapFree=0/0 [pid=4068] ppid=4067 vsize=66660 CPUtime=1.51 /proc/4068/stat : 4068 (cupt) R 4067 4068 17872 34816 17872 4202496 10493 7221 0 0 134 10 5 2 20 0 1 0 30440841 68259840 10044 18446744073709551615 4194304 5184042 140735586634928 140735586632360 139654094731611 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4068/statm: 16665 10044 851 242 0 9227 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 66660 [startup+3.1002 s] /proc/loadavg: 0.99 0.97 0.97 2/56 4088 /proc/meminfo: memFree=544904/1022884 swapFree=0/0 [pid=4068] ppid=4067 vsize=70328 CPUtime=3.11 /proc/4068/stat : 4068 (cupt) R 4067 4068 17872 34816 17872 4202496 11840 7221 0 0 292 12 5 2 20 0 1 0 30440841 72015872 10621 18446744073709551615 4194304 5184042 140735586634928 140735586632232 139654111150967 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4068/statm: 17582 10621 851 242 0 10144 0 Current children cumulated CPU time (s) 3.11 Current children cumulated vsize (KiB) 70328 [startup+6.3002 s] /proc/loadavg: 0.99 0.97 0.97 2/56 4088 /proc/meminfo: memFree=541432/1022884 swapFree=0/0 [pid=4068] ppid=4067 vsize=74424 CPUtime=6.29 /proc/4068/stat : 4068 (cupt) R 4067 4068 17872 34816 17872 4202496 13690 7221 0 0 608 14 5 2 20 0 1 0 30440841 76210176 11446 18446744073709551615 4194304 5184042 140735586634928 140735586632360 139654111088709 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4068/statm: 18606 11446 851 242 0 11168 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 74424 [startup+12.7002 s] /proc/loadavg: 0.99 0.97 0.97 2/56 4088 /proc/meminfo: memFree=533992/1022884 swapFree=0/0 [pid=4068] ppid=4067 vsize=82908 CPUtime=12.67 /proc/4068/stat : 4068 (cupt) R 4067 4068 17872 34816 17872 4202496 17656 7221 0 0 1242 18 5 2 20 0 1 0 30440841 84897792 13363 18446744073709551615 4194304 5184042 140735586634928 140735586632232 139654103147041 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4068/statm: 20727 13363 851 242 0 13289 0 Current children cumulated CPU time (s) 12.67 Current children cumulated vsize (KiB) 82908 [startup+25.5002 s] /proc/loadavg: 0.99 0.97 0.97 2/56 4088 /proc/meminfo: memFree=519980/1022884 swapFree=0/0 [pid=4068] ppid=4067 vsize=99440 CPUtime=25.42 /proc/4068/stat : 4068 (cupt) R 4067 4068 17872 34816 17872 4202496 24992 7221 0 0 2512 23 5 2 20 0 1 0 30440841 101826560 16602 18446744073709551615 4194304 5184042 140735586634928 140735586632232 139654111065504 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4068/statm: 24860 16602 851 242 0 17422 0 Current children cumulated CPU time (s) 25.42 Current children cumulated vsize (KiB) 99440 [startup+51.1002 s] /proc/loadavg: 0.99 0.97 0.97 2/56 4088 /proc/meminfo: memFree=496420/1022884 swapFree=0/0 [pid=4068] ppid=4067 vsize=132208 CPUtime=50.92 /proc/4068/stat : 4068 (cupt) R 4067 4068 17872 34816 17872 4202496 39122 7221 0 0 5054 31 5 2 20 0 1 0 30440841 135380992 22539 18446744073709551615 4194304 5184042 140735586634928 140735586632376 139654095373529 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4068/statm: 33052 22539 851 242 0 25614 0 Current children cumulated CPU time (s) 50.92 Current children cumulated vsize (KiB) 132208 [startup+102.3 s] /proc/loadavg: 0.99 0.97 0.97 2/56 4088 /proc/meminfo: memFree=456492/1022884 swapFree=0/0 [pid=4068] ppid=4067 vsize=197744 CPUtime=101.92 /proc/4068/stat : 4068 (cupt) R 4067 4068 17872 34816 17872 4202496 65329 7221 0 0 10134 51 5 2 20 0 1 0 30440841 202489856 32361 18446744073709551615 4194304 5184042 140735586634928 140735586632360 139654111032176 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4068/statm: 49436 32361 851 242 0 41998 0 Current children cumulated CPU time (s) 101.92 Current children cumulated vsize (KiB) 197744 [startup+162.3 s] /proc/loadavg: 0.99 0.97 0.97 2/56 4088 /proc/meminfo: memFree=413712/1022884 swapFree=0/0 [pid=4068] ppid=4067 vsize=328964 CPUtime=161.68 /proc/4068/stat : 4068 (cupt) R 4067 4068 17872 34816 17872 4202496 108752 7221 0 0 16091 70 5 2 20 0 1 0 30440841 336859136 43015 18446744073709551615 4194304 5184042 140735586634928 140735586632376 139654094721503 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4068/statm: 82241 43015 851 242 0 74803 0 Current children cumulated CPU time (s) 161.68 Current children cumulated vsize (KiB) 328964 [startup+222.303 s] /proc/loadavg: 0.99 0.97 0.97 2/56 4088 /proc/meminfo: memFree=375768/1022884 swapFree=0/0 [pid=4068] ppid=4067 vsize=329556 CPUtime=221.43 /proc/4068/stat : 4068 (cupt) R 4067 4068 17872 34816 17872 4202496 118231 7221 0 0 22059 77 5 2 20 0 1 0 30440841 337465344 52494 18446744073709551615 4194304 5184042 140735586634928 140735586632232 139654103146944 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4068/statm: 82389 52494 851 242 0 74951 0 Current children cumulated CPU time (s) 221.43 Current children cumulated vsize (KiB) 329556 [startup+282.3 s] /proc/loadavg: 0.99 0.97 0.97 2/56 4088 /proc/meminfo: memFree=330508/1022884 swapFree=0/0 [pid=4068] ppid=4067 vsize=331604 CPUtime=281.19 /proc/4068/stat : 4068 (cupt) R 4067 4068 17872 34816 17872 4202496 129723 7221 0 0 28022 90 5 2 20 0 1 0 30440841 339562496 63986 18446744073709551615 4194304 5184042 140735586634928 140735586629192 139654111123117 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4068/statm: 82901 63986 851 242 0 75463 0 Current children cumulated CPU time (s) 281.19 Current children cumulated vsize (KiB) 331604 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 0.99 0.97 0.97 2/56 4088 /proc/meminfo: memFree=312652/1022884 swapFree=0/0 [pid=4068] ppid=4067 vsize=331604 CPUtime=298.83 /proc/4068/stat : 4068 (cupt) R 4067 4068 17872 34816 17872 4202496 133970 7221 0 0 29778 98 5 2 20 0 1 0 30440841 339562496 68233 18446744073709551615 4194304 5184042 140735586634928 140735586629192 139654111065072 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4068/statm: 82901 68233 851 242 0 75463 0 Current children cumulated CPU time (s) 298.83 Current children cumulated vsize (KiB) 331604 Sending Terminated to process tree (bottom up) Sleeping 2 seconds Solver just ended. Dumping a history of the last processes samples [startup+300 s] /proc/loadavg: 0.99 0.97 0.97 2/56 4088 /proc/meminfo: memFree=312652/1022884 swapFree=0/0 [pid=4068] ppid=4067 vsize=331604 CPUtime=298.83 /proc/4068/stat : 4068 (cupt) R 4067 4068 17872 34816 17872 4202496 133970 7221 0 0 29778 98 5 2 20 0 1 0 30440841 339562496 68233 18446744073709551615 4194304 5184042 140735586634928 140735586629192 139654111065072 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/4068/statm: 82901 68233 851 242 0 75463 0 Current children cumulated CPU time (s) 298.83 Current children cumulated vsize (KiB) 331604 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.028 CPU time (s): 298.863 CPU user time (s): 297.839 CPU system time (s): 1.02406 CPU usage (%): 99.6114 Max. virtual memory (cumulated for all children) (KiB): 460040 getrusage(RUSAGE_CHILDREN,...) data: user time used= 297.839 system time used= 1.02406 maximum resident set size= 302608 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 141191 page faults= 0 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 52 involuntary context switches= 4474 runsolver used 0.340021 second user time and 0.856053 second system time The end