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/80.runsolver.smart smart --config-file=/home/cbse/var/lib/smart/config install xscreensaver-nognome amanda-server libtemplate-plugin-calendar-simple-perl libmm13 gap-core 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: 1.03 0.99 0.93 2/53 6579 /proc/meminfo: memFree=452376/1022884 swapFree=0/0 [pid=6579] ppid=6578 vsize=3152 CPUtime=0 /proc/6579/stat : 6579 (runsolver) R 6578 2806 2806 34818 2806 4202560 0 0 0 0 0 0 0 0 20 0 1 0 2804078 3227648 32 18446744073709551615 134512640 134586868 4294404576 4294402624 4152001584 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/6579/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.170393 s] /proc/loadavg: 1.03 0.99 0.93 2/53 6579 /proc/meminfo: memFree=452376/1022884 swapFree=0/0 [pid=6579] ppid=6578 vsize=118376 CPUtime=0.16 /proc/6579/stat : 6579 (smart) R 6578 6579 2806 34818 2806 4202496 12457 413 0 0 10 6 0 0 20 0 1 0 2804078 121217024 7349 18446744073709551615 4194304 6763684 140735258580560 140735258576552 5518020 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/6579/statm: 29594 7349 1058 628 0 6147 0 Current children cumulated CPU time (s) 0.16 Current children cumulated vsize (KiB) 118376 [startup+0.200282 s] /proc/loadavg: 1.03 0.99 0.93 2/53 6579 /proc/meminfo: memFree=452376/1022884 swapFree=0/0 [pid=6579] ppid=6578 vsize=120168 CPUtime=0.18 /proc/6579/stat : 6579 (smart) R 6578 6579 2806 34818 2806 4202496 13517 413 0 0 12 6 0 0 20 0 1 0 2804078 123052032 7739 18446744073709551615 4194304 6763684 140735258580560 140735258576360 140679001762143 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/6579/statm: 30042 7739 1058 628 0 6595 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 120168 [startup+0.30024 s] /proc/loadavg: 1.03 0.99 0.93 2/53 6579 /proc/meminfo: memFree=452376/1022884 swapFree=0/0 [pid=6579] ppid=6578 vsize=134452 CPUtime=0.28 /proc/6579/stat : 6579 (smart) R 6578 6579 2806 34818 2806 4202496 17093 413 0 0 22 6 0 0 20 0 1 0 2804078 137678848 11312 18446744073709551615 4194304 6763684 140735258580560 140735258576360 140679001895033 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/6579/statm: 33613 11312 1059 628 0 10166 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 134452 [startup+0.700184 s] /proc/loadavg: 1.03 0.99 0.93 2/53 6579 /proc/meminfo: memFree=452376/1022884 swapFree=0/0 [pid=6579] ppid=6578 vsize=196848 CPUtime=0.68 /proc/6579/stat : 6579 (smart) R 6578 6579 2806 34818 2806 4202496 35788 413 0 0 57 11 0 0 20 0 1 0 2804078 201572352 26921 18446744073709551615 4194304 6763684 140735258580560 140735258576104 140679001830865 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/6579/statm: 49212 26921 1059 628 0 25765 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 196848 [startup+1.5002 s] /proc/loadavg: 1.03 0.99 0.93 2/54 6582 /proc/meminfo: memFree=339032/1022884 swapFree=0/0 [pid=6579] ppid=6578 vsize=207780 CPUtime=1.48 /proc/6579/stat : 6579 (smart) R 6578 6579 2806 34818 2806 4202496 44752 413 0 0 134 14 0 0 20 0 1 0 2804078 212766720 29707 18446744073709551615 4194304 6763684 140735258580560 140735258575696 4414197 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/6579/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: 1.03 0.99 0.93 2/54 6582 /proc/meminfo: memFree=337420/1022884 swapFree=0/0 [pid=6579] ppid=6578 vsize=207780 CPUtime=3.07 /proc/6579/stat : 6579 (smart) R 6578 6579 2806 34818 2806 4202496 44765 413 0 0 293 14 0 0 20 0 1 0 2804078 212766720 29711 18446744073709551615 4194304 6763684 140735258580560 140735258577512 140679002451674 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/6579/statm: 51945 29711 1073 628 0 28498 0 Current children cumulated CPU time (s) 3.07 Current children cumulated vsize (KiB) 207780 [startup+6.30019 s] /proc/loadavg: 1.03 0.99 0.93 2/54 6582 /proc/meminfo: memFree=337420/1022884 swapFree=0/0 [pid=6579] ppid=6578 vsize=207780 CPUtime=6.26 /proc/6579/stat : 6579 (smart) R 6578 6579 2806 34818 2806 4202496 44765 413 0 0 612 14 0 0 20 0 1 0 2804078 212766720 29711 18446744073709551615 4194304 6763684 140735258580560 140735258577512 140679002451674 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/6579/statm: 51945 29711 1073 628 0 28498 0 Current children cumulated CPU time (s) 6.26 Current children cumulated vsize (KiB) 207780 [startup+12.7002 s] /proc/loadavg: 1.02 0.99 0.93 2/54 6582 /proc/meminfo: memFree=337296/1022884 swapFree=0/0 [pid=6579] ppid=6578 vsize=207780 CPUtime=12.64 /proc/6579/stat : 6579 (smart) R 6578 6579 2806 34818 2806 4202496 44765 413 0 0 1250 14 0 0 20 0 1 0 2804078 212766720 29711 18446744073709551615 4194304 6763684 140735258580560 140735258577512 140679002451674 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/6579/statm: 51945 29711 1073 628 0 28498 0 Current children cumulated CPU time (s) 12.64 Current children cumulated vsize (KiB) 207780 [startup+25.5002 s] /proc/loadavg: 1.02 0.99 0.93 2/54 6582 /proc/meminfo: memFree=337296/1022884 swapFree=0/0 [pid=6579] ppid=6578 vsize=207780 CPUtime=25.39 /proc/6579/stat : 6579 (smart) R 6578 6579 2806 34818 2806 4202496 44765 413 0 0 2525 14 0 0 20 0 1 0 2804078 212766720 29711 18446744073709551615 4194304 6763684 140735258580560 140735258577512 140678984703681 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/6579/statm: 51945 29711 1073 628 0 28498 0 Current children cumulated CPU time (s) 25.39 Current children cumulated vsize (KiB) 207780 [startup+51.1002 s] /proc/loadavg: 1.01 0.99 0.93 2/54 6582 /proc/meminfo: memFree=337296/1022884 swapFree=0/0 [pid=6579] ppid=6578 vsize=207780 CPUtime=50.9 /proc/6579/stat : 6579 (smart) R 6578 6579 2806 34818 2806 4202496 44765 413 0 0 5076 14 0 0 20 0 1 0 2804078 212766720 29711 18446744073709551615 4194304 6763684 140735258580560 140735258577512 5221439 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/6579/statm: 51945 29711 1073 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.00 0.99 0.93 2/54 6590 /proc/meminfo: memFree=336800/1022884 swapFree=0/0 [pid=6579] ppid=6578 vsize=207780 CPUtime=101.89 /proc/6579/stat : 6579 (smart) R 6578 6579 2806 34818 2806 4202496 44765 413 0 0 10175 14 0 0 20 0 1 0 2804078 212766720 29711 18446744073709551615 4194304 6763684 140735258580560 140735258577512 5221439 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/6579/statm: 51945 29711 1073 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.99 0.93 2/54 6590 /proc/meminfo: memFree=336800/1022884 swapFree=0/0 [pid=6579] ppid=6578 vsize=207780 CPUtime=161.68 /proc/6579/stat : 6579 (smart) R 6578 6579 2806 34818 2806 4202496 44765 413 0 0 16154 14 0 0 20 0 1 0 2804078 212766720 29711 18446744073709551615 4194304 6763684 140735258580560 140735258577512 140679002451674 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/6579/statm: 51945 29711 1073 628 0 28498 0 Current children cumulated CPU time (s) 161.68 Current children cumulated vsize (KiB) 207780 [startup+222.303 s] /proc/loadavg: 1.00 0.99 0.93 2/54 6590 /proc/meminfo: memFree=336800/1022884 swapFree=0/0 [pid=6579] ppid=6578 vsize=207780 CPUtime=221.46 /proc/6579/stat : 6579 (smart) R 6578 6579 2806 34818 2806 4202496 44765 413 0 0 22132 14 0 0 20 0 1 0 2804078 212766720 29711 18446744073709551615 4194304 6763684 140735258580560 140735258577512 140679002453512 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/6579/statm: 51945 29711 1073 628 0 28498 0 Current children cumulated CPU time (s) 221.46 Current children cumulated vsize (KiB) 207780 [startup+282.3 s] /proc/loadavg: 1.00 0.99 0.93 2/54 6590 /proc/meminfo: memFree=336800/1022884 swapFree=0/0 [pid=6579] ppid=6578 vsize=207780 CPUtime=281.25 /proc/6579/stat : 6579 (smart) R 6578 6579 2806 34818 2806 4202496 44765 413 0 0 28111 14 0 0 20 0 1 0 2804078 212766720 29711 18446744073709551615 4194304 6763684 140735258580560 140735258577512 5221439 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/6579/statm: 51945 29711 1073 628 0 28498 0 Current children cumulated CPU time (s) 281.25 Current children cumulated vsize (KiB) 207780 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 1.00 0.99 0.93 2/54 6590 /proc/meminfo: memFree=336800/1022884 swapFree=0/0 [pid=6579] ppid=6578 vsize=207780 CPUtime=298.89 /proc/6579/stat : 6579 (smart) R 6578 6579 2806 34818 2806 4202496 44765 413 0 0 29875 14 0 0 20 0 1 0 2804078 212766720 29711 18446744073709551615 4194304 6763684 140735258580560 140735258577512 140678984703681 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/6579/statm: 51945 29711 1073 628 0 28498 0 Current children cumulated CPU time (s) 298.89 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.99 0.93 2/54 6590 /proc/meminfo: memFree=336800/1022884 swapFree=0/0 [pid=6579] ppid=6578 vsize=207780 CPUtime=298.89 /proc/6579/stat : 6579 (smart) R 6578 6579 2806 34818 2806 4202496 44765 413 0 0 29875 14 0 0 20 0 1 0 2804078 212766720 29711 18446744073709551615 4194304 6763684 140735258580560 140735258577512 140678984703681 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/6579/statm: 51945 29711 1073 628 0 28498 0 Current children cumulated CPU time (s) 298.89 Current children cumulated vsize (KiB) 207780 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.014 CPU time (s): 298.915 CPU user time (s): 298.755 CPU system time (s): 0.16001 CPU usage (%): 99.6335 Max. virtual memory (cumulated for all children) (KiB): 207780 getrusage(RUSAGE_CHILDREN,...) data: user time used= 298.755 system time used= 0.16001 maximum resident set size= 120000 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 45178 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= 4375 runsolver used 0.340021 second user time and 0.744046 second system time The end