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/54.runsolver.smart smart --config-file=/home/cbse/var/lib/smart/config install gtk2-engines-industrial scripts4ticker heroes-sound-tracks xfonts-intl-chinese-big ksimus-boolean 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.92 2/53 5716 /proc/meminfo: memFree=454796/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=26808 CPUtime=0 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 627 0 0 0 0 0 0 0 20 0 1 0 2280150 27451392 516 18446744073709551615 4194304 6763684 140737051403216 140737051393752 4353659 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 6702 516 375 628 0 161 0 [startup+0.204899 s] /proc/loadavg: 0.99 0.98 0.92 2/53 5716 /proc/meminfo: memFree=454796/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=120676 CPUtime=0.19 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 13702 413 0 0 13 6 0 0 20 0 1 0 2280150 123572224 7921 18446744073709551615 4194304 6763684 140737051403216 140737051399208 139964887654519 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 30169 7921 1059 628 0 6722 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 120676 [startup+0.300243 s] /proc/loadavg: 0.99 0.98 0.92 2/53 5716 /proc/meminfo: memFree=454796/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=134876 CPUtime=0.29 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 17209 413 0 0 21 8 0 0 20 0 1 0 2280150 138113024 11428 18446744073709551615 4194304 6763684 140737051403216 140737051399208 4726896 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 33719 11428 1059 628 0 10272 0 Current children cumulated CPU time (s) 0.29 Current children cumulated vsize (KiB) 134876 [startup+0.400256 s] /proc/loadavg: 0.99 0.98 0.92 2/53 5716 /proc/meminfo: memFree=454796/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=154608 CPUtime=0.39 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 22184 413 0 0 31 8 0 0 20 0 1 0 2280150 158318592 16403 18446744073709551615 4194304 6763684 140737051403216 140737051399208 5520656 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 38652 16403 1059 628 0 15205 0 Current children cumulated CPU time (s) 0.39 Current children cumulated vsize (KiB) 154608 [startup+0.700184 s] /proc/loadavg: 0.99 0.98 0.92 2/53 5716 /proc/meminfo: memFree=454796/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=196460 CPUtime=0.69 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 35648 413 0 0 58 11 0 0 20 0 1 0 2280150 201175040 26781 18446744073709551615 4194304 6763684 140737051403216 140737051398760 139964887633288 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 49115 26781 1059 628 0 25668 0 Current children cumulated CPU time (s) 0.69 Current children cumulated vsize (KiB) 196460 [startup+1.50019 s] /proc/loadavg: 0.99 0.98 0.92 2/54 5719 /proc/meminfo: memFree=341576/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=207776 CPUtime=1.48 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 44751 413 0 0 136 12 0 0 20 0 1 0 2280150 212762624 29707 18446744073709551615 4194304 6763684 140737051403216 140737051398352 5743575 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 51944 29707 1069 628 0 28497 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 207776 [startup+3.10022 s] /proc/loadavg: 0.99 0.98 0.92 2/54 5719 /proc/meminfo: memFree=339840/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=207776 CPUtime=3.08 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 44763 413 0 0 296 12 0 0 20 0 1 0 2280150 212762624 29710 18446744073709551615 4194304 6763684 140737051403216 140737051400168 139964870463152 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 51944 29710 1072 628 0 28497 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 207776 [startup+6.30019 s] /proc/loadavg: 0.99 0.98 0.92 2/54 5719 /proc/meminfo: memFree=339716/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=207776 CPUtime=6.26 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 44763 413 0 0 614 12 0 0 20 0 1 0 2280150 212762624 29710 18446744073709551615 4194304 6763684 140737051403216 140737051400168 139964888211162 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 51944 29710 1072 628 0 28497 0 Current children cumulated CPU time (s) 6.26 Current children cumulated vsize (KiB) 207776 [startup+12.7002 s] /proc/loadavg: 0.99 0.98 0.92 2/54 5719 /proc/meminfo: memFree=339592/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=207776 CPUtime=12.64 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 44763 413 0 0 1252 12 0 0 20 0 1 0 2280150 212762624 29710 18446744073709551615 4194304 6763684 140737051403216 140737051400168 139964888212992 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 51944 29710 1072 628 0 28497 0 Current children cumulated CPU time (s) 12.64 Current children cumulated vsize (KiB) 207776 [startup+25.5028 s] /proc/loadavg: 0.99 0.98 0.92 2/54 5719 /proc/meminfo: memFree=339592/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=207776 CPUtime=25.4 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 44763 413 0 0 2528 12 0 0 20 0 1 0 2280150 212762624 29710 18446744073709551615 4194304 6763684 140737051403216 140737051400168 139964888211296 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 51944 29710 1072 628 0 28497 0 Current children cumulated CPU time (s) 25.4 Current children cumulated vsize (KiB) 207776 [startup+51.1002 s] /proc/loadavg: 0.99 0.98 0.92 2/54 5719 /proc/meminfo: memFree=339592/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=207776 CPUtime=50.9 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 44763 413 0 0 5078 12 0 0 20 0 1 0 2280150 212762624 29710 18446744073709551615 4194304 6763684 140737051403216 140737051400168 139964888211296 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 51944 29710 1072 628 0 28497 0 Current children cumulated CPU time (s) 50.9 Current children cumulated vsize (KiB) 207776 [startup+102.3 s] /proc/loadavg: 0.99 0.98 0.92 2/54 5719 /proc/meminfo: memFree=339468/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=207776 CPUtime=101.92 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 44764 413 0 0 10180 12 0 0 20 0 1 0 2280150 212762624 29711 18446744073709551615 4194304 6763684 140737051403216 140737051400168 139964888213004 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 51944 29711 1073 628 0 28497 0 Current children cumulated CPU time (s) 101.92 Current children cumulated vsize (KiB) 207776 [startup+162.3 s] /proc/loadavg: 0.99 0.98 0.92 2/54 5719 /proc/meminfo: memFree=339468/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=207776 CPUtime=161.7 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 44764 413 0 0 16158 12 0 0 20 0 1 0 2280150 212762624 29711 18446744073709551615 4194304 6763684 140737051403216 140737051400168 4533856 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 51944 29711 1073 628 0 28497 0 Current children cumulated CPU time (s) 161.7 Current children cumulated vsize (KiB) 207776 Solver just ended. Dumping a history of the last processes samples [startup+179.3 s] /proc/loadavg: 0.99 0.98 0.92 2/54 5719 /proc/meminfo: memFree=339468/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=207776 CPUtime=178.63 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 44764 413 0 0 17851 12 0 0 20 0 1 0 2280150 212762624 29711 18446744073709551615 4194304 6763684 140737051403216 140737051400168 139964888211310 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 51944 29711 1073 628 0 28497 0 Current children cumulated CPU time (s) 178.63 Current children cumulated vsize (KiB) 207776 [startup+192.1 s] /proc/loadavg: 0.99 0.98 0.92 2/54 5719 /proc/meminfo: memFree=339468/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=207776 CPUtime=191.39 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 44764 413 0 0 19127 12 0 0 20 0 1 0 2280150 212762624 29711 18446744073709551615 4194304 6763684 140737051403216 140737051400168 139964870463169 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 51944 29711 1073 628 0 28497 0 Current children cumulated CPU time (s) 191.39 Current children cumulated vsize (KiB) 207776 [startup+198.5 s] /proc/loadavg: 0.99 0.98 0.92 2/54 5719 /proc/meminfo: memFree=339468/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=207776 CPUtime=197.76 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 44764 413 0 0 19764 12 0 0 20 0 1 0 2280150 212762624 29711 18446744073709551615 4194304 6763684 140737051403216 140737051400168 139964888211296 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 51944 29711 1073 628 0 28497 0 Current children cumulated CPU time (s) 197.76 Current children cumulated vsize (KiB) 207776 [startup+201.7 s] /proc/loadavg: 0.99 0.98 0.92 2/54 5719 /proc/meminfo: memFree=339468/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=207776 CPUtime=200.95 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 44764 413 0 0 20083 12 0 0 20 0 1 0 2280150 212762624 29711 18446744073709551615 4194304 6763684 140737051403216 140737051400168 139964888213021 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 51944 29711 1073 628 0 28497 0 Current children cumulated CPU time (s) 200.95 Current children cumulated vsize (KiB) 207776 [startup+202.5 s] /proc/loadavg: 0.99 0.98 0.92 2/54 5719 /proc/meminfo: memFree=339468/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=207776 CPUtime=201.75 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 44764 413 0 0 20163 12 0 0 20 0 1 0 2280150 212762624 29711 18446744073709551615 4194304 6763684 140737051403216 140737051400168 139964888211162 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 51944 29711 1073 628 0 28497 0 Current children cumulated CPU time (s) 201.75 Current children cumulated vsize (KiB) 207776 [startup+203.3 s] /proc/loadavg: 0.99 0.98 0.92 2/54 5719 /proc/meminfo: memFree=339468/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=207776 CPUtime=202.55 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 44764 413 0 0 20243 12 0 0 20 0 1 0 2280150 212762624 29711 18446744073709551615 4194304 6763684 140737051403216 140737051400168 139964870463169 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 51944 29711 1073 628 0 28497 0 Current children cumulated CPU time (s) 202.55 Current children cumulated vsize (KiB) 207776 [startup+203.703 s] /proc/loadavg: 0.99 0.98 0.92 2/54 5719 /proc/meminfo: memFree=339468/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=207792 CPUtime=202.94 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 44797 413 0 0 20282 12 0 0 20 0 1 0 2280150 212779008 29720 18446744073709551615 4194304 6763684 140737051403216 140737051402104 5763124 0 0 16777216 0 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 51948 29720 1079 628 0 28501 0 Current children cumulated CPU time (s) 202.94 Current children cumulated vsize (KiB) 207792 [startup+203.8 s] /proc/loadavg: 0.99 0.98 0.92 2/54 5719 /proc/meminfo: memFree=339468/1022884 swapFree=0/0 [pid=5716] ppid=5715 vsize=207792 CPUtime=203.04 /proc/5716/stat : 5716 (smart) R 5715 5716 2806 34818 2806 4202496 44797 413 0 0 20292 12 0 0 20 0 1 0 2280150 212779008 29720 18446744073709551615 4194304 6763684 140737051403216 140737051402104 5764419 0 0 16777216 0 0 0 0 17 0 0 0 0 0 0 /proc/5716/statm: 51948 29720 1079 628 0 28501 0 Current children cumulated CPU time (s) 203.04 Current children cumulated vsize (KiB) 207792 Child status: 0 Real time (s): 203.848 CPU time (s): 203.101 CPU user time (s): 202.973 CPU system time (s): 0.128008 CPU usage (%): 99.6333 Max. virtual memory (cumulated for all children) (KiB): 207792 getrusage(RUSAGE_CHILDREN,...) data: user time used= 202.973 system time used= 0.128008 maximum resident set size= 120000 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 45631 page faults= 0 swaps= 0 block input operations= 0 block output operations= 96 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 6 involuntary context switches= 2959 runsolver used 0.220013 second user time and 0.532033 second system time The end