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/49.runsolver.smart smart --config-file=/home/cbse/var/lib/smart/config install pathogen contact-lookup-applet libdbd-pg-perl exim gnusound 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.91 2/53 5451 /proc/meminfo: memFree=454812/1022884 swapFree=0/0 [pid=5451] ppid=5450 vsize=3152 CPUtime=0 /proc/5451/stat : 5451 (runsolver) R 5450 2806 2806 34818 2806 4202560 0 0 0 0 0 0 0 0 20 0 1 0 2163025 3227648 33 18446744073709551615 134512640 134586868 4291207968 4291206016 4151223344 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/5451/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.124602 s] /proc/loadavg: 0.99 0.97 0.91 2/53 5451 /proc/meminfo: memFree=454812/1022884 swapFree=0/0 [pid=5451] ppid=5450 vsize=107184 CPUtime=0.11 /proc/5451/stat : 5451 (smart) R 5450 5451 2806 34818 2806 4202496 8412 0 0 0 8 3 0 0 20 0 1 0 2163025 109756416 5582 18446744073709551615 4194304 6763684 140735632737264 140735632719648 139733241612518 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/5451/statm: 26796 5582 1048 628 0 4379 0 Current children cumulated CPU time (s) 0.11 Current children cumulated vsize (KiB) 107184 [startup+0.200244 s] /proc/loadavg: 0.99 0.97 0.91 2/53 5451 /proc/meminfo: memFree=454812/1022884 swapFree=0/0 [pid=5451] ppid=5450 vsize=120424 CPUtime=0.19 /proc/5451/stat : 5451 (smart) R 5450 5451 2806 34818 2806 4202496 13607 412 0 0 15 4 0 0 20 0 1 0 2163025 123314176 7829 18446744073709551615 4194304 6763684 140735632737264 140735632733320 4726994 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/5451/statm: 30106 7829 1058 628 0 6659 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 120424 [startup+0.300249 s] /proc/loadavg: 0.99 0.97 0.91 2/53 5451 /proc/meminfo: memFree=454812/1022884 swapFree=0/0 [pid=5451] ppid=5450 vsize=134880 CPUtime=0.28 /proc/5451/stat : 5451 (smart) R 5450 5451 2806 34818 2806 4202496 17205 412 0 0 24 4 0 0 20 0 1 0 2163025 138117120 11424 18446744073709551615 4194304 6763684 140735632737264 140735632733256 4411535 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/5451/statm: 33720 11424 1059 628 0 10273 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 134880 [startup+0.700183 s] /proc/loadavg: 0.99 0.97 0.91 2/53 5451 /proc/meminfo: memFree=454812/1022884 swapFree=0/0 [pid=5451] ppid=5450 vsize=196064 CPUtime=0.69 /proc/5451/stat : 5451 (smart) R 5450 5451 2806 34818 2806 4202496 35616 412 0 0 61 8 0 0 20 0 1 0 2163025 200769536 26749 18446744073709551615 4194304 6763684 140735632737264 140735632733256 139733224299008 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/5451/statm: 49016 26749 1059 628 0 25569 0 Current children cumulated CPU time (s) 0.69 Current children cumulated vsize (KiB) 196064 [startup+1.5002 s] /proc/loadavg: 0.99 0.97 0.91 2/54 5454 /proc/meminfo: memFree=341592/1022884 swapFree=0/0 [pid=5451] ppid=5450 vsize=207780 CPUtime=1.48 /proc/5451/stat : 5451 (smart) R 5450 5451 2806 34818 2806 4202496 44752 412 0 0 137 11 0 0 20 0 1 0 2163025 212766720 29707 18446744073709551615 4194304 6763684 140735632737264 140735632732400 139733241423078 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5451/statm: 51945 29707 1069 628 0 28498 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 207780 [startup+3.10019 s] /proc/loadavg: 0.99 0.97 0.91 2/54 5454 /proc/meminfo: memFree=339980/1022884 swapFree=0/0 [pid=5451] ppid=5450 vsize=207780 CPUtime=3.08 /proc/5451/stat : 5451 (smart) R 5450 5451 2806 34818 2806 4202496 44762 412 0 0 297 11 0 0 20 0 1 0 2163025 212766720 29708 18446744073709551615 4194304 6763684 140735632737264 140735632734216 139733242033672 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5451/statm: 51945 29708 1070 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.99 0.97 0.91 2/54 5454 /proc/meminfo: memFree=339980/1022884 swapFree=0/0 [pid=5451] ppid=5450 vsize=207780 CPUtime=6.27 /proc/5451/stat : 5451 (smart) R 5450 5451 2806 34818 2806 4202496 44762 412 0 0 616 11 0 0 20 0 1 0 2163025 212766720 29708 18446744073709551615 4194304 6763684 140735632737264 140735632734216 4412514 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5451/statm: 51945 29708 1070 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.99 0.97 0.91 2/54 5454 /proc/meminfo: memFree=339856/1022884 swapFree=0/0 [pid=5451] ppid=5450 vsize=207780 CPUtime=12.64 /proc/5451/stat : 5451 (smart) R 5450 5451 2806 34818 2806 4202496 44762 412 0 0 1253 11 0 0 20 0 1 0 2163025 212766720 29708 18446744073709551615 4194304 6763684 140735632737264 140735632734216 139733242031834 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5451/statm: 51945 29708 1070 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.99 0.97 0.91 2/54 5454 /proc/meminfo: memFree=339856/1022884 swapFree=0/0 [pid=5451] ppid=5450 vsize=207780 CPUtime=25.39 /proc/5451/stat : 5451 (smart) R 5450 5451 2806 34818 2806 4202496 44762 412 0 0 2528 11 0 0 20 0 1 0 2163025 212766720 29708 18446744073709551615 4194304 6763684 140735632737264 140735632734216 139733224283841 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5451/statm: 51945 29708 1070 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.99 0.97 0.91 2/54 5454 /proc/meminfo: memFree=339856/1022884 swapFree=0/0 [pid=5451] ppid=5450 vsize=207780 CPUtime=50.9 /proc/5451/stat : 5451 (smart) R 5450 5451 2806 34818 2806 4202496 44762 412 0 0 5079 11 0 0 20 0 1 0 2163025 212766720 29708 18446744073709551615 4194304 6763684 140735632737264 140735632734216 139733242031968 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5451/statm: 51945 29708 1070 628 0 28498 0 Current children cumulated CPU time (s) 50.9 Current children cumulated vsize (KiB) 207780 [startup+102.3 s] /proc/loadavg: 1.07 0.99 0.92 3/54 5591 /proc/meminfo: memFree=339104/1022884 swapFree=0/0 [pid=5451] ppid=5450 vsize=207780 CPUtime=100.65 /proc/5451/stat : 5451 (smart) R 5450 5451 2806 34818 2806 4202496 44762 412 0 0 10054 11 0 0 20 0 1 0 2163025 212766720 29708 18446744073709551615 4194304 6763684 140735632737264 140735632734216 139733242031834 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5451/statm: 51945 29708 1070 628 0 28498 0 Current children cumulated CPU time (s) 100.65 Current children cumulated vsize (KiB) 207780 [startup+162.3 s] /proc/loadavg: 1.06 1.00 0.93 2/54 5683 /proc/meminfo: memFree=339608/1022884 swapFree=0/0 [pid=5451] ppid=5450 vsize=207780 CPUtime=158.88 /proc/5451/stat : 5451 (smart) R 5450 5451 2806 34818 2806 4202496 44762 412 0 0 15877 11 0 0 20 0 1 0 2163025 212766720 29708 18446744073709551615 4194304 6763684 140735632737264 140735632734216 5155177 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5451/statm: 51945 29708 1070 628 0 28498 0 Current children cumulated CPU time (s) 158.88 Current children cumulated vsize (KiB) 207780 [startup+222.303 s] /proc/loadavg: 1.02 1.00 0.93 2/54 5683 /proc/meminfo: memFree=339608/1022884 swapFree=0/0 [pid=5451] ppid=5450 vsize=207780 CPUtime=218.67 /proc/5451/stat : 5451 (smart) R 5450 5451 2806 34818 2806 4202496 44764 412 0 0 21856 11 0 0 20 0 1 0 2163025 212766720 29710 18446744073709551615 4194304 6763684 140735632737264 140735632734216 139733242031968 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5451/statm: 51945 29710 1072 628 0 28498 0 Current children cumulated CPU time (s) 218.67 Current children cumulated vsize (KiB) 207780 [startup+282.3 s] /proc/loadavg: 1.01 1.00 0.93 2/54 5683 /proc/meminfo: memFree=339608/1022884 swapFree=0/0 [pid=5451] ppid=5450 vsize=207780 CPUtime=278.45 /proc/5451/stat : 5451 (smart) R 5450 5451 2806 34818 2806 4202496 44764 412 0 0 27834 11 0 0 20 0 1 0 2163025 212766720 29710 18446744073709551615 4194304 6763684 140735632737264 140735632734216 139733224283841 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5451/statm: 51945 29710 1072 628 0 28498 0 Current children cumulated CPU time (s) 278.45 Current children cumulated vsize (KiB) 207780 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 1.00 1.00 0.93 2/54 5683 /proc/meminfo: memFree=339608/1022884 swapFree=0/0 [pid=5451] ppid=5450 vsize=207780 CPUtime=296.09 /proc/5451/stat : 5451 (smart) R 5450 5451 2806 34818 2806 4202496 44764 412 0 0 29598 11 0 0 20 0 1 0 2163025 212766720 29710 18446744073709551615 4194304 6763684 140735632737264 140735632734216 139733242035512 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5451/statm: 51945 29710 1072 628 0 28498 0 Current children cumulated CPU time (s) 296.09 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 1.00 0.93 2/54 5683 /proc/meminfo: memFree=339608/1022884 swapFree=0/0 [pid=5451] ppid=5450 vsize=207780 CPUtime=296.09 /proc/5451/stat : 5451 (smart) R 5450 5451 2806 34818 2806 4202496 44764 412 0 0 29598 11 0 0 20 0 1 0 2163025 212766720 29710 18446744073709551615 4194304 6763684 140735632737264 140735632734216 139733242035512 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5451/statm: 51945 29710 1072 628 0 28498 0 Current children cumulated CPU time (s) 296.09 Current children cumulated vsize (KiB) 207780 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.014 CPU time (s): 296.115 CPU user time (s): 295.99 CPU system time (s): 0.124007 CPU usage (%): 98.7003 Max. virtual memory (cumulated for all children) (KiB): 207780 getrusage(RUSAGE_CHILDREN,...) data: user time used= 295.99 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= 45176 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= 5157 runsolver used 0.32802 second user time and 0.764047 second system time The end