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/logs/1.runsolver.smart smart --config-file=/home/cbse/var/lib/smart/config install libgnome2-gconf-perl libroy1-prof python-simpy libchipcard20 libeb7-dev 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.78 0.36 0.13 2/57 3722 /proc/meminfo: memFree=455448/1022884 swapFree=0/0 [pid=3722] ppid=3721 vsize=27248 CPUtime=0 /proc/3722/stat : 3722 (smart) R 3721 3722 2806 34818 2806 4202496 895 0 0 0 0 0 0 0 20 0 1 0 922092 27901952 769 18446744073709551615 4194304 6763684 140735463111968 140735463097592 4364559 0 0 16781312 2 0 0 0 17 0 0 0 0 0 0 /proc/3722/statm: 6812 769 491 628 0 271 0 [startup+0.197727 s] /proc/loadavg: 0.78 0.36 0.13 2/57 3722 /proc/meminfo: memFree=455448/1022884 swapFree=0/0 [pid=3722] ppid=3721 vsize=120680 CPUtime=0.19 /proc/3722/stat : 3722 (smart) R 3721 3722 2806 34818 2806 4202496 13695 411 0 0 16 3 0 0 20 0 1 0 922092 123576320 7915 18446744073709551615 4194304 6763684 140735463111968 140735463108024 140612101801651 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/3722/statm: 30170 7915 1059 628 0 6723 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 120680 [startup+0.200235 s] /proc/loadavg: 0.78 0.36 0.13 2/57 3722 /proc/meminfo: memFree=455448/1022884 swapFree=0/0 [pid=3722] ppid=3721 vsize=120936 CPUtime=0.19 /proc/3722/stat : 3722 (smart) R 3721 3722 2806 34818 2806 4202496 13784 411 0 0 16 3 0 0 20 0 1 0 922092 123838464 8004 18446744073709551615 4194304 6763684 140735463111968 140735463107960 140612120695805 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/3722/statm: 30234 8004 1059 628 0 6787 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 120936 [startup+0.300178 s] /proc/loadavg: 0.78 0.36 0.13 2/57 3722 /proc/meminfo: memFree=455448/1022884 swapFree=0/0 [pid=3722] ppid=3721 vsize=136188 CPUtime=0.29 /proc/3722/stat : 3722 (smart) R 3721 3722 2806 34818 2806 4202496 17589 411 0 0 25 4 0 0 20 0 1 0 922092 139456512 11809 18446744073709551615 4194304 6763684 140735463111968 140735463108024 4363509 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/3722/statm: 34047 11809 1059 628 0 10600 0 Current children cumulated CPU time (s) 0.29 Current children cumulated vsize (KiB) 136188 [startup+0.70019 s] /proc/loadavg: 0.78 0.36 0.13 2/57 3722 /proc/meminfo: memFree=455448/1022884 swapFree=0/0 [pid=3722] ppid=3721 vsize=200668 CPUtime=0.69 /proc/3722/stat : 3722 (smart) R 3721 3722 2806 34818 2806 4202496 36746 411 0 0 60 9 0 0 20 0 1 0 922092 205484032 27880 18446744073709551615 4194304 6763684 140735463111968 140735463107688 140612101832244 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/3722/statm: 50167 27880 1059 628 0 26720 0 Current children cumulated CPU time (s) 0.69 Current children cumulated vsize (KiB) 200668 [startup+1.5002 s] /proc/loadavg: 0.78 0.36 0.13 2/58 3725 /proc/meminfo: memFree=341988/1022884 swapFree=0/0 [pid=3722] ppid=3721 vsize=207780 CPUtime=1.49 /proc/3722/stat : 3722 (smart) R 3721 3722 2806 34818 2806 4202496 44749 411 0 0 137 12 0 0 20 0 1 0 922092 212766720 29707 18446744073709551615 4194304 6763684 140735463111968 140735463106664 140612101829442 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/3722/statm: 51945 29707 1069 628 0 28498 0 Current children cumulated CPU time (s) 1.49 Current children cumulated vsize (KiB) 207780 [startup+3.10019 s] /proc/loadavg: 0.80 0.37 0.14 2/58 3725 /proc/meminfo: memFree=340376/1022884 swapFree=0/0 [pid=3722] ppid=3721 vsize=207780 CPUtime=3.08 /proc/3722/stat : 3722 (smart) R 3721 3722 2806 34818 2806 4202496 44761 411 0 0 296 12 0 0 20 0 1 0 922092 212766720 29710 18446744073709551615 4194304 6763684 140735463111968 140735463108920 4533775 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/3722/statm: 51945 29710 1072 628 0 28498 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 207780 [startup+6.30019 s] /proc/loadavg: 0.80 0.37 0.14 2/58 3725 /proc/meminfo: memFree=340128/1022884 swapFree=0/0 [pid=3722] ppid=3721 vsize=207780 CPUtime=6.27 /proc/3722/stat : 3722 (smart) R 3721 3722 2806 34818 2806 4202496 44761 411 0 0 615 12 0 0 20 0 1 0 922092 212766720 29710 18446744073709551615 4194304 6763684 140735463111968 140735463108920 140612102450910 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/3722/statm: 51945 29710 1072 628 0 28498 0 Current children cumulated CPU time (s) 6.27 Current children cumulated vsize (KiB) 207780 [startup+12.7002 s] /proc/loadavg: 0.83 0.39 0.15 2/58 3725 /proc/meminfo: memFree=340004/1022884 swapFree=0/0 [pid=3722] ppid=3721 vsize=207780 CPUtime=12.64 /proc/3722/stat : 3722 (smart) R 3721 3722 2806 34818 2806 4202496 44761 411 0 0 1252 12 0 0 20 0 1 0 922092 212766720 29710 18446744073709551615 4194304 6763684 140735463111968 140735463108920 140612102450906 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/3722/statm: 51945 29710 1072 628 0 28498 0 Current children cumulated CPU time (s) 12.64 Current children cumulated vsize (KiB) 207780 [startup+25.5002 s] /proc/loadavg: 0.86 0.41 0.16 2/58 3725 /proc/meminfo: memFree=340004/1022884 swapFree=0/0 [pid=3722] ppid=3721 vsize=207780 CPUtime=25.39 /proc/3722/stat : 3722 (smart) R 3721 3722 2806 34818 2806 4202496 44761 411 0 0 2527 12 0 0 20 0 1 0 922092 212766720 29710 18446744073709551615 4194304 6763684 140735463111968 140735463108920 140612102450906 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/3722/statm: 51945 29710 1072 628 0 28498 0 Current children cumulated CPU time (s) 25.39 Current children cumulated vsize (KiB) 207780 [startup+51.1002 s] /proc/loadavg: 0.90 0.46 0.18 2/58 3725 /proc/meminfo: memFree=339880/1022884 swapFree=0/0 [pid=3722] ppid=3721 vsize=207780 CPUtime=50.89 /proc/3722/stat : 3722 (smart) R 3721 3722 2806 34818 2806 4202496 44761 411 0 0 5077 12 0 0 20 0 1 0 922092 212766720 29710 18446744073709551615 4194304 6763684 140735463111968 140735463108920 4414162 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/3722/statm: 51945 29710 1072 628 0 28498 0 Current children cumulated CPU time (s) 50.89 Current children cumulated vsize (KiB) 207780 [startup+102.3 s] /proc/loadavg: 1.01 0.56 0.23 2/58 3725 /proc/meminfo: memFree=339880/1022884 swapFree=0/0 [pid=3722] ppid=3721 vsize=207780 CPUtime=101.89 /proc/3722/stat : 3722 (smart) R 3721 3722 2806 34818 2806 4202496 44761 411 0 0 10177 12 0 0 20 0 1 0 922092 212766720 29710 18446744073709551615 4194304 6763684 140735463111968 140735463108920 140612102454584 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/3722/statm: 51945 29710 1072 628 0 28498 0 Current children cumulated CPU time (s) 101.89 Current children cumulated vsize (KiB) 207780 [startup+162.3 s] /proc/loadavg: 1.00 0.64 0.27 2/58 3725 /proc/meminfo: memFree=339880/1022884 swapFree=0/0 [pid=3722] ppid=3721 vsize=207780 CPUtime=161.66 /proc/3722/stat : 3722 (smart) R 3721 3722 2806 34818 2806 4202496 44761 411 0 0 16154 12 0 0 20 0 1 0 922092 212766720 29710 18446744073709551615 4194304 6763684 140735463111968 140735463108920 140612102450906 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/3722/statm: 51945 29710 1072 628 0 28498 0 Current children cumulated CPU time (s) 161.66 Current children cumulated vsize (KiB) 207780 [startup+222.307 s] /proc/loadavg: 1.00 0.70 0.31 2/58 3725 /proc/meminfo: memFree=339880/1022884 swapFree=0/0 [pid=3722] ppid=3721 vsize=207780 CPUtime=221.43 /proc/3722/stat : 3722 (smart) R 3721 3722 2806 34818 2806 4202496 44761 411 0 0 22131 12 0 0 20 0 1 0 922092 212766720 29710 18446744073709551615 4194304 6763684 140735463111968 140735463108920 140612084702913 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/3722/statm: 51945 29710 1072 628 0 28498 0 Current children cumulated CPU time (s) 221.43 Current children cumulated vsize (KiB) 207780 [startup+282.3 s] /proc/loadavg: 1.00 0.75 0.35 2/58 3725 /proc/meminfo: memFree=339880/1022884 swapFree=0/0 [pid=3722] ppid=3721 vsize=207780 CPUtime=281.19 /proc/3722/stat : 3722 (smart) R 3721 3722 2806 34818 2806 4202496 44761 411 0 0 28107 12 0 0 20 0 1 0 922092 212766720 29710 18446744073709551615 4194304 6763684 140735463111968 140735463108920 140612084687552 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/3722/statm: 51945 29710 1072 628 0 28498 0 Current children cumulated CPU time (s) 281.19 Current children cumulated vsize (KiB) 207780 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 1.00 0.77 0.37 2/58 3725 /proc/meminfo: memFree=339880/1022884 swapFree=0/0 [pid=3722] ppid=3721 vsize=207780 CPUtime=298.83 /proc/3722/stat : 3722 (smart) R 3721 3722 2806 34818 2806 4202496 44761 411 0 0 29871 12 0 0 20 0 1 0 922092 212766720 29710 18446744073709551615 4194304 6763684 140735463111968 140735463108920 140612084702913 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/3722/statm: 51945 29710 1072 628 0 28498 0 Current children cumulated CPU time (s) 298.83 Current children cumulated vsize (KiB) 207780 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: 1.00 0.77 0.37 2/58 3725 /proc/meminfo: memFree=339880/1022884 swapFree=0/0 [pid=3722] ppid=3721 vsize=207780 CPUtime=298.83 /proc/3722/stat : 3722 (smart) R 3721 3722 2806 34818 2806 4202496 44761 411 0 0 29871 12 0 0 20 0 1 0 922092 212766720 29710 18446744073709551615 4194304 6763684 140735463111968 140735463108920 140612084702913 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/3722/statm: 51945 29710 1072 628 0 28498 0 Current children cumulated CPU time (s) 298.83 Current children cumulated vsize (KiB) 207780 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.014 CPU time (s): 298.839 CPU user time (s): 298.715 CPU system time (s): 0.124007 CPU usage (%): 99.6082 Max. virtual memory (cumulated for all children) (KiB): 207780 getrusage(RUSAGE_CHILDREN,...) data: user time used= 298.715 system time used= 0.124007 maximum resident set size= 120000 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 45172 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= 7 involuntary context switches= 4630 runsolver used 0.432027 second user time and 0.732045 second system time The end