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/155.runsolver.smart smart --config-file=/home/cbse/var/lib/smart/config remove libmlgtk-ocaml-dev kompare kdebase-kio-plugins kdeadmin liblzo1 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 Current StackSize limit: 8192 KiB [startup+0 s] /proc/loadavg: 0.99 0.97 0.98 2/53 31906 /proc/meminfo: memFree=380688/1022884 swapFree=0/0 [pid=31906] ppid=31905 vsize=3152 CPUtime=0 /proc/31906/stat : 31906 (runsolver) R 31905 2806 2806 34818 2806 4202560 0 0 0 0 0 0 0 0 20 0 1 0 18878808 3227648 33 18446744073709551615 134512640 134586868 4286862896 4286860944 4151710768 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/31906/statm: 788 33 0 19 0 73 0 [startup+0.1613 s] /proc/loadavg: 0.99 0.97 0.98 2/53 31906 /proc/meminfo: memFree=380688/1022884 swapFree=0/0 [pid=31906] ppid=31905 vsize=134320 CPUtime=0.15 /proc/31906/stat : 31906 (smart) R 31905 31906 2806 34818 2806 4202496 10731 0 0 0 12 3 0 0 20 0 1 0 18878808 137543680 9450 18446744073709551615 4194304 6763684 140733354034000 140733354028712 139932712504829 0 0 16781312 2 0 0 0 17 0 0 0 0 0 0 /proc/31906/statm: 33580 9450 1043 628 0 11163 0 Current children cumulated CPU time (s) 0.15 Current children cumulated vsize (KiB) 134320 [startup+0.200251 s] /proc/loadavg: 0.99 0.97 0.98 2/53 31906 /proc/meminfo: memFree=380688/1022884 swapFree=0/0 [pid=31906] ppid=31905 vsize=134028 CPUtime=0.19 /proc/31906/stat : 31906 (smart) R 31905 31906 2806 34818 2806 4202496 15040 0 0 0 15 4 0 0 20 0 1 0 18878808 137244672 12222 18446744073709551615 4194304 6763684 140733354034000 140733354029000 4533572 0 0 16781312 2 0 0 0 17 0 0 0 0 0 0 /proc/31906/statm: 33507 12222 1043 628 0 11090 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 134028 [startup+0.300255 s] /proc/loadavg: 0.99 0.97 0.98 2/53 31906 /proc/meminfo: memFree=380688/1022884 swapFree=0/0 [pid=31906] ppid=31905 vsize=136216 CPUtime=0.29 /proc/31906/stat : 31906 (smart) R 31905 31906 2806 34818 2806 4202496 21503 413 0 0 24 5 0 0 20 0 1 0 18878808 139485184 11827 18446744073709551615 4194304 6763684 140733354034000 140733354029976 5511447 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/31906/statm: 34054 11827 1058 628 0 10607 0 Current children cumulated CPU time (s) 0.29 Current children cumulated vsize (KiB) 136216 [startup+0.700176 s] /proc/loadavg: 0.99 0.97 0.98 2/53 31906 /proc/meminfo: memFree=380688/1022884 swapFree=0/0 [pid=31906] ppid=31905 vsize=186184 CPUtime=0.68 /proc/31906/stat : 31906 (smart) R 31905 31906 2806 34818 2806 4202496 35536 413 0 0 60 8 0 0 20 0 1 0 18878808 190652416 24259 18446744073709551615 4194304 6763684 140733354034000 140733354030056 5763084 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/31906/statm: 46546 24259 1059 628 0 23099 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 186184 [startup+1.50019 s] /proc/loadavg: 0.99 0.97 0.98 2/54 31909 /proc/meminfo: memFree=238940/1022884 swapFree=0/0 [pid=31906] ppid=31905 vsize=289632 CPUtime=1.48 /proc/31906/stat : 31906 (smart) R 31905 31906 2806 34818 2806 4202496 67585 413 0 0 132 16 0 0 20 0 1 0 18878808 296583168 50160 18446744073709551615 4194304 6763684 140733354034000 140733354030056 5763144 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/31906/statm: 72408 50160 1059 628 0 48961 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 289632 [startup+3.1002 s] /proc/loadavg: 0.99 0.97 0.98 2/54 31909 /proc/meminfo: memFree=115808/1022884 swapFree=0/0 [pid=31906] ppid=31905 vsize=347852 CPUtime=3.07 /proc/31906/stat : 31906 (smart) R 31905 31906 2806 34818 2806 4202496 94463 413 0 0 285 22 0 0 20 0 1 0 18878808 356200448 64718 18446744073709551615 4194304 6763684 140733354034000 140733354030040 4926592 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/31906/statm: 86963 64718 1068 628 0 63516 0 Current children cumulated CPU time (s) 3.07 Current children cumulated vsize (KiB) 347852 [startup+6.30019 s] /proc/loadavg: 0.99 0.97 0.98 2/54 31909 /proc/meminfo: memFree=107624/1022884 swapFree=0/0 [pid=31906] ppid=31905 vsize=365568 CPUtime=6.27 /proc/31906/stat : 31906 (smart) R 31905 31906 2806 34818 2806 4202496 98901 413 0 0 603 24 0 0 20 0 1 0 18878808 374341632 69145 18446744073709551615 4194304 6763684 140733354034000 140733354030952 139932695334593 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/31906/statm: 91392 69145 1073 628 0 67945 0 Current children cumulated CPU time (s) 6.27 Current children cumulated vsize (KiB) 365568 [startup+12.7002 s] /proc/loadavg: 0.99 0.97 0.98 2/54 31909 /proc/meminfo: memFree=107500/1022884 swapFree=0/0 [pid=31906] ppid=31905 vsize=365568 CPUtime=12.64 /proc/31906/stat : 31906 (smart) R 31905 31906 2806 34818 2806 4202496 98901 413 0 0 1240 24 0 0 20 0 1 0 18878808 374341632 69145 18446744073709551615 4194304 6763684 140733354034000 140733354030952 139932695334593 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/31906/statm: 91392 69145 1073 628 0 67945 0 Current children cumulated CPU time (s) 12.64 Current children cumulated vsize (KiB) 365568 [startup+25.5002 s] /proc/loadavg: 0.99 0.97 0.98 2/54 31909 /proc/meminfo: memFree=107500/1022884 swapFree=0/0 [pid=31906] ppid=31905 vsize=365568 CPUtime=25.39 /proc/31906/stat : 31906 (smart) R 31905 31906 2806 34818 2806 4202496 98901 413 0 0 2515 24 0 0 20 0 1 0 18878808 374341632 69145 18446744073709551615 4194304 6763684 140733354034000 140733354030952 139932713082586 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/31906/statm: 91392 69145 1073 628 0 67945 0 Current children cumulated CPU time (s) 25.39 Current children cumulated vsize (KiB) 365568 [startup+51.1002 s] /proc/loadavg: 0.99 0.97 0.98 2/54 31909 /proc/meminfo: memFree=107500/1022884 swapFree=0/0 [pid=31906] ppid=31905 vsize=365568 CPUtime=50.9 /proc/31906/stat : 31906 (smart) R 31905 31906 2806 34818 2806 4202496 98906 413 0 0 5064 26 0 0 20 0 1 0 18878808 374341632 69145 18446744073709551615 4194304 6763684 140733354034000 140733354030952 139932713082586 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/31906/statm: 91392 69145 1073 628 0 67945 0 Current children cumulated CPU time (s) 50.9 Current children cumulated vsize (KiB) 365568 [startup+102.3 s] /proc/loadavg: 0.99 0.97 0.98 2/54 31909 /proc/meminfo: memFree=107376/1022884 swapFree=0/0 [pid=31906] ppid=31905 vsize=365568 CPUtime=101.91 /proc/31906/stat : 31906 (smart) R 31905 31906 2806 34818 2806 4202496 98906 413 0 0 10161 30 0 0 20 0 1 0 18878808 374341632 69145 18446744073709551615 4194304 6763684 140733354034000 140733354030952 139932713082586 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/31906/statm: 91392 69145 1073 628 0 67945 0 Current children cumulated CPU time (s) 101.91 Current children cumulated vsize (KiB) 365568 [startup+162.3 s] /proc/loadavg: 0.99 0.97 0.98 2/54 31909 /proc/meminfo: memFree=107376/1022884 swapFree=0/0 [pid=31906] ppid=31905 vsize=365568 CPUtime=161.68 /proc/31906/stat : 31906 (smart) R 31905 31906 2806 34818 2806 4202496 98906 413 0 0 16136 32 0 0 20 0 1 0 18878808 374341632 69145 18446744073709551615 4194304 6763684 140733354034000 140733354030952 139932695334593 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/31906/statm: 91392 69145 1073 628 0 67945 0 Current children cumulated CPU time (s) 161.68 Current children cumulated vsize (KiB) 365568 [startup+222.303 s] /proc/loadavg: 0.99 0.97 0.98 2/54 31909 /proc/meminfo: memFree=107376/1022884 swapFree=0/0 [pid=31906] ppid=31905 vsize=365568 CPUtime=221.46 /proc/31906/stat : 31906 (smart) R 31905 31906 2806 34818 2806 4202496 98906 413 0 0 22108 38 0 0 20 0 1 0 18878808 374341632 69145 18446744073709551615 4194304 6763684 140733354034000 140733354030952 139932713082720 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/31906/statm: 91392 69145 1073 628 0 67945 0 Current children cumulated CPU time (s) 221.46 Current children cumulated vsize (KiB) 365568 [startup+282.3 s] /proc/loadavg: 0.99 0.97 0.98 2/54 31917 /proc/meminfo: memFree=106880/1022884 swapFree=0/0 [pid=31906] ppid=31905 vsize=365568 CPUtime=281.21 /proc/31906/stat : 31906 (smart) R 31905 31906 2806 34818 2806 4202496 98906 413 0 0 28078 43 0 0 20 0 1 0 18878808 374341632 69145 18446744073709551615 4194304 6763684 140733354034000 140733354030952 139932695334593 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/31906/statm: 91392 69145 1073 628 0 67945 0 Current children cumulated CPU time (s) 281.21 Current children cumulated vsize (KiB) 365568 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 0.99 0.97 0.98 2/54 31917 /proc/meminfo: memFree=106880/1022884 swapFree=0/0 [pid=31906] ppid=31905 vsize=365568 CPUtime=298.85 /proc/31906/stat : 31906 (smart) R 31905 31906 2806 34818 2806 4202496 98906 413 0 0 29842 43 0 0 20 0 1 0 18878808 374341632 69145 18446744073709551615 4194304 6763684 140733354034000 140733354030952 139932713082720 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/31906/statm: 91392 69145 1073 628 0 67945 0 Current children cumulated CPU time (s) 298.85 Current children cumulated vsize (KiB) 365568 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.98 2/54 31917 /proc/meminfo: memFree=106880/1022884 swapFree=0/0 [pid=31906] ppid=31905 vsize=365568 CPUtime=298.85 /proc/31906/stat : 31906 (smart) R 31905 31906 2806 34818 2806 4202496 98906 413 0 0 29842 43 0 0 20 0 1 0 18878808 374341632 69145 18446744073709551615 4194304 6763684 140733354034000 140733354030952 139932713082720 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/31906/statm: 91392 69145 1073 628 0 67945 0 Current children cumulated CPU time (s) 298.85 Current children cumulated vsize (KiB) 365568 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.034 CPU time (s): 298.887 CPU user time (s): 298.427 CPU system time (s): 0.460028 CPU usage (%): 99.6178 Max. virtual memory (cumulated for all children) (KiB): 365568 getrusage(RUSAGE_CHILDREN,...) data: user time used= 298.427 system time used= 0.460028 maximum resident set size= 276580 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 99319 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= 6 involuntary context switches= 4470 runsolver used 0.716044 second user time and 0.416026 second system time The end