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/22.runsolver.smart smart --config-file=/home/cbse/var/lib/smart/config install python2.3-psycopg tct python-xml guile-library ale 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.98 0.98 2/53 18095 /proc/meminfo: memFree=367192/1022884 swapFree=0/0 [pid=18095] ppid=18094 vsize=26808 CPUtime=0 /proc/18095/stat : 18095 (smart) R 18094 18095 2806 34818 2806 4202496 596 0 0 0 0 0 0 0 20 0 1 0 10024329 27451392 489 18446744073709551615 4194304 6763684 140736633545936 140736633536472 5519599 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/18095/statm: 6702 489 366 628 0 161 0 [startup+0.18908 s] /proc/loadavg: 0.99 0.98 0.98 2/53 18095 /proc/meminfo: memFree=367192/1022884 swapFree=0/0 [pid=18095] ppid=18094 vsize=130140 CPUtime=0.18 /proc/18095/stat : 18095 (smart) R 18094 18095 2806 34818 2806 4202496 14077 0 0 0 15 3 0 0 20 0 1 0 10024329 133263360 11260 18446744073709551615 4194304 6763684 140736633545936 140736633540952 140013843125245 0 0 16781312 2 0 0 0 17 0 0 0 0 0 0 /proc/18095/statm: 32535 11260 1043 628 0 10118 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 130140 [startup+0.200248 s] /proc/loadavg: 0.99 0.98 0.98 2/53 18095 /proc/meminfo: memFree=367192/1022884 swapFree=0/0 [pid=18095] ppid=18094 vsize=132220 CPUtime=0.19 /proc/18095/stat : 18095 (smart) R 18094 18095 2806 34818 2806 4202496 14637 0 0 0 16 3 0 0 20 0 1 0 10024329 135393280 11820 18446744073709551615 4194304 6763684 140736633545936 140736633540888 140013824261578 0 0 16781312 2 0 0 0 17 0 0 0 0 0 0 /proc/18095/statm: 33055 11820 1043 628 0 10638 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 132220 [startup+0.300185 s] /proc/loadavg: 0.99 0.98 0.98 2/53 18095 /proc/meminfo: memFree=367192/1022884 swapFree=0/0 [pid=18095] ppid=18094 vsize=135820 CPUtime=0.28 /proc/18095/stat : 18095 (smart) R 18094 18095 2806 34818 2806 4202496 21194 414 0 0 24 4 0 0 20 0 1 0 10024329 139079680 11728 18446744073709551615 4194304 6763684 140736633545936 140736633541928 5763084 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/18095/statm: 33955 11728 1058 628 0 10508 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 135820 [startup+0.700199 s] /proc/loadavg: 0.99 0.98 0.98 2/53 18095 /proc/meminfo: memFree=367192/1022884 swapFree=0/0 [pid=18095] ppid=18094 vsize=183356 CPUtime=0.68 /proc/18095/stat : 18095 (smart) R 18094 18095 2806 34818 2806 4202496 34642 414 0 0 60 8 0 0 20 0 1 0 10024329 187756544 23598 18446744073709551615 4194304 6763684 140736633545936 140736633541992 140013824323648 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/18095/statm: 45839 23598 1059 628 0 22392 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 183356 [startup+1.50019 s] /proc/loadavg: 0.99 0.98 0.98 2/54 18098 /proc/meminfo: memFree=228800/1022884 swapFree=0/0 [pid=18095] ppid=18094 vsize=285836 CPUtime=1.48 /proc/18095/stat : 18095 (smart) R 18094 18095 2806 34818 2806 4202496 66391 414 0 0 132 16 0 0 20 0 1 0 10024329 292696064 49199 18446744073709551615 4194304 6763684 140736633545936 140736633541928 5511944 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/18095/statm: 71459 49199 1059 628 0 48012 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 285836 [startup+3.1002 s] /proc/loadavg: 0.99 0.98 0.98 2/54 18098 /proc/meminfo: memFree=164568/1022884 swapFree=0/0 [pid=18095] ppid=18094 vsize=335124 CPUtime=3.07 /proc/18095/stat : 18095 (smart) R 18094 18095 2806 34818 2806 4202496 91074 414 0 0 283 24 0 0 20 0 1 0 10024329 343166976 61561 18446744073709551615 4194304 6763684 140736633545936 140736633541976 4411810 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/18095/statm: 83781 61561 1068 628 0 60334 0 Current children cumulated CPU time (s) 3.07 Current children cumulated vsize (KiB) 335124 [startup+6.30018 s] /proc/loadavg: 0.99 0.98 0.98 2/54 18098 /proc/meminfo: memFree=116456/1022884 swapFree=0/0 [pid=18095] ppid=18094 vsize=343324 CPUtime=6.27 /proc/18095/stat : 18095 (smart) R 18094 18095 2806 34818 2806 4202496 93113 414 0 0 602 25 0 0 20 0 1 0 10024329 351563776 63589 18446744073709551615 4194304 6763684 140736633545936 140736633542888 140013807132362 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/18095/statm: 85831 63589 1073 628 0 62384 0 Current children cumulated CPU time (s) 6.27 Current children cumulated vsize (KiB) 343324 [startup+12.7003 s] /proc/loadavg: 0.99 0.98 0.98 2/54 18098 /proc/meminfo: memFree=116332/1022884 swapFree=0/0 [pid=18095] ppid=18094 vsize=343324 CPUtime=12.64 /proc/18095/stat : 18095 (smart) R 18094 18095 2806 34818 2806 4202496 93116 414 0 0 1239 25 0 0 20 0 1 0 10024329 351563776 63589 18446744073709551615 4194304 6763684 140736633545936 140736633542888 140013824880346 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/18095/statm: 85831 63589 1073 628 0 62384 0 Current children cumulated CPU time (s) 12.64 Current children cumulated vsize (KiB) 343324 [startup+25.5002 s] /proc/loadavg: 0.99 0.98 0.98 2/54 18098 /proc/meminfo: memFree=116332/1022884 swapFree=0/0 [pid=18095] ppid=18094 vsize=343324 CPUtime=25.39 /proc/18095/stat : 18095 (smart) R 18094 18095 2806 34818 2806 4202496 93119 414 0 0 2514 25 0 0 20 0 1 0 10024329 351563776 63589 18446744073709551615 4194304 6763684 140736633545936 140736633542888 140013824880480 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/18095/statm: 85831 63589 1073 628 0 62384 0 Current children cumulated CPU time (s) 25.39 Current children cumulated vsize (KiB) 343324 [startup+51.1002 s] /proc/loadavg: 0.99 0.98 0.98 2/54 18098 /proc/meminfo: memFree=116332/1022884 swapFree=0/0 [pid=18095] ppid=18094 vsize=343324 CPUtime=50.89 /proc/18095/stat : 18095 (smart) R 18094 18095 2806 34818 2806 4202496 93119 414 0 0 5064 25 0 0 20 0 1 0 10024329 351563776 63589 18446744073709551615 4194304 6763684 140736633545936 140736633542888 140013807132353 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/18095/statm: 85831 63589 1073 628 0 62384 0 Current children cumulated CPU time (s) 50.89 Current children cumulated vsize (KiB) 343324 [startup+102.3 s] /proc/loadavg: 0.99 0.98 0.98 2/54 18098 /proc/meminfo: memFree=116208/1022884 swapFree=0/0 [pid=18095] ppid=18094 vsize=343324 CPUtime=101.9 /proc/18095/stat : 18095 (smart) R 18094 18095 2806 34818 2806 4202496 93119 414 0 0 10164 26 0 0 20 0 1 0 10024329 351563776 63589 18446744073709551615 4194304 6763684 140736633545936 140736633542888 4415378 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/18095/statm: 85831 63589 1073 628 0 62384 0 Current children cumulated CPU time (s) 101.9 Current children cumulated vsize (KiB) 343324 [startup+162.3 s] /proc/loadavg: 0.99 0.98 0.98 2/54 18098 /proc/meminfo: memFree=116208/1022884 swapFree=0/0 [pid=18095] ppid=18094 vsize=343324 CPUtime=161.67 /proc/18095/stat : 18095 (smart) R 18094 18095 2806 34818 2806 4202496 93119 414 0 0 16141 26 0 0 20 0 1 0 10024329 351563776 63589 18446744073709551615 4194304 6763684 140736633545936 140736633542888 140013824880480 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/18095/statm: 85831 63589 1073 628 0 62384 0 Current children cumulated CPU time (s) 161.67 Current children cumulated vsize (KiB) 343324 [startup+222.303 s] /proc/loadavg: 0.99 0.98 0.98 2/54 18098 /proc/meminfo: memFree=116208/1022884 swapFree=0/0 [pid=18095] ppid=18094 vsize=343324 CPUtime=221.44 /proc/18095/stat : 18095 (smart) R 18094 18095 2806 34818 2806 4202496 93119 414 0 0 22118 26 0 0 20 0 1 0 10024329 351563776 63589 18446744073709551615 4194304 6763684 140736633545936 140736633542888 140013824880346 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/18095/statm: 85831 63589 1073 628 0 62384 0 Current children cumulated CPU time (s) 221.44 Current children cumulated vsize (KiB) 343324 [startup+282.3 s] /proc/loadavg: 0.99 0.98 0.98 2/54 18098 /proc/meminfo: memFree=116208/1022884 swapFree=0/0 [pid=18095] ppid=18094 vsize=343324 CPUtime=281.21 /proc/18095/stat : 18095 (smart) R 18094 18095 2806 34818 2806 4202496 93119 414 0 0 28095 26 0 0 20 0 1 0 10024329 351563776 63589 18446744073709551615 4194304 6763684 140736633545936 140736633542888 140013807132320 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/18095/statm: 85831 63589 1073 628 0 62384 0 Current children cumulated CPU time (s) 281.21 Current children cumulated vsize (KiB) 343324 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 0.99 0.98 0.98 2/54 18098 /proc/meminfo: memFree=116208/1022884 swapFree=0/0 [pid=18095] ppid=18094 vsize=343324 CPUtime=298.84 /proc/18095/stat : 18095 (smart) R 18094 18095 2806 34818 2806 4202496 93119 414 0 0 29858 26 0 0 20 0 1 0 10024329 351563776 63589 18446744073709551615 4194304 6763684 140736633545936 140736633542888 140013824880346 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/18095/statm: 85831 63589 1073 628 0 62384 0 Current children cumulated CPU time (s) 298.84 Current children cumulated vsize (KiB) 343324 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.98 0.98 2/54 18098 /proc/meminfo: memFree=116208/1022884 swapFree=0/0 [pid=18095] ppid=18094 vsize=343324 CPUtime=298.84 /proc/18095/stat : 18095 (smart) R 18094 18095 2806 34818 2806 4202496 93119 414 0 0 29858 26 0 0 20 0 1 0 10024329 351563776 63589 18446744073709551615 4194304 6763684 140736633545936 140736633542888 140013824880346 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/18095/statm: 85831 63589 1073 628 0 62384 0 Current children cumulated CPU time (s) 298.84 Current children cumulated vsize (KiB) 343324 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.03 CPU time (s): 298.883 CPU user time (s): 298.599 CPU system time (s): 0.284017 CPU usage (%): 99.6176 Max. virtual memory (cumulated for all children) (KiB): 344144 getrusage(RUSAGE_CHILDREN,...) data: user time used= 298.599 system time used= 0.284017 maximum resident set size= 254964 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 93533 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= 4444 runsolver used 0.460028 second user time and 0.864054 second system time The end