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-sid/logs/64.runsolver.smart smart --config-file=/home/cbse/var/lib/smart/config install lg-issue103 rbldnsd libexpat-ocaml kernel-headers-2.6.8-13-em64t-p4 mergelog 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.92 0.98 0.99 2/53 27730 /proc/meminfo: memFree=389620/1022884 swapFree=0/0 [pid=27730] ppid=27729 vsize=3152 CPUtime=0 /proc/27730/stat : 27730 (runsolver) R 27729 2806 2806 34818 2806 4202560 0 0 0 0 0 0 0 0 20 0 1 0 16130491 3227648 33 18446744073709551615 134512640 134586868 4294872832 4294870880 4151346224 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/27730/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.157725 s] /proc/loadavg: 0.92 0.98 0.99 2/53 27730 /proc/meminfo: memFree=389620/1022884 swapFree=0/0 [pid=27730] ppid=27729 vsize=121632 CPUtime=0.15 /proc/27730/stat : 27730 (smart) R 27729 27730 2806 34818 2806 4202496 10452 0 0 0 13 2 0 0 20 0 1 0 16130491 124551168 9172 18446744073709551615 4194304 6763684 140736000099552 140736000094552 4409376 0 0 16781312 2 0 0 0 17 0 0 0 0 0 0 /proc/27730/statm: 30408 9172 1043 628 0 7991 0 Current children cumulated CPU time (s) 0.15 Current children cumulated vsize (KiB) 121632 [startup+0.20026 s] /proc/loadavg: 0.92 0.98 0.99 2/53 27730 /proc/meminfo: memFree=389620/1022884 swapFree=0/0 [pid=27730] ppid=27729 vsize=134416 CPUtime=0.19 /proc/27730/stat : 27730 (smart) R 27729 27730 2806 34818 2806 4202496 15161 0 0 0 16 3 0 0 20 0 1 0 16130491 137641984 12344 18446744073709551615 4194304 6763684 140736000099552 140736000094632 140286632494077 0 0 16781312 2 0 0 0 17 0 0 0 0 0 0 /proc/27730/statm: 33604 12344 1043 628 0 11187 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 134416 [startup+0.300262 s] /proc/loadavg: 0.92 0.98 0.99 2/53 27730 /proc/meminfo: memFree=389620/1022884 swapFree=0/0 [pid=27730] ppid=27729 vsize=136212 CPUtime=0.28 /proc/27730/stat : 27730 (smart) R 27729 27730 2806 34818 2806 4202496 21503 414 0 0 22 6 0 0 20 0 1 0 16130491 139481088 11828 18446744073709551615 4194304 6763684 140736000099552 140736000095528 5763274 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/27730/statm: 34053 11828 1058 628 0 10606 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 136212 [startup+0.700186 s] /proc/loadavg: 0.92 0.98 0.99 2/53 27730 /proc/meminfo: memFree=389620/1022884 swapFree=0/0 [pid=27730] ppid=27729 vsize=186192 CPUtime=0.68 /proc/27730/stat : 27730 (smart) R 27729 27730 2806 34818 2806 4202496 35534 414 0 0 59 9 0 0 20 0 1 0 16130491 190660608 24259 18446744073709551615 4194304 6763684 140736000099552 140736000095608 5763091 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/27730/statm: 46548 24259 1059 628 0 23101 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 186192 [startup+1.5002 s] /proc/loadavg: 0.92 0.98 0.99 2/54 27733 /proc/meminfo: memFree=247888/1022884 swapFree=0/0 [pid=27730] ppid=27729 vsize=289636 CPUtime=1.48 /proc/27730/stat : 27730 (smart) R 27729 27730 2806 34818 2806 4202496 67583 414 0 0 133 15 0 0 20 0 1 0 16130491 296587264 50160 18446744073709551615 4194304 6763684 140736000099552 140736000095608 5518020 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/27730/statm: 72409 50160 1059 628 0 48962 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 289636 [startup+3.1002 s] /proc/loadavg: 0.92 0.98 0.99 2/54 27733 /proc/meminfo: memFree=125500/1022884 swapFree=0/0 [pid=27730] ppid=27729 vsize=347072 CPUtime=3.08 /proc/27730/stat : 27730 (smart) R 27729 27730 2806 34818 2806 4202496 94266 414 0 0 286 22 0 0 20 0 1 0 16130491 355401728 64521 18446744073709551615 4194304 6763684 140736000099552 140736000095592 140286613628301 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/27730/statm: 86768 64521 1068 628 0 63321 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 347072 [startup+6.3002 s] /proc/loadavg: 0.93 0.98 0.99 2/54 27733 /proc/meminfo: memFree=116572/1022884 swapFree=0/0 [pid=27730] ppid=27729 vsize=365564 CPUtime=6.27 /proc/27730/stat : 27730 (smart) R 27729 27730 2806 34818 2806 4202496 98899 414 0 0 604 23 0 0 20 0 1 0 16130491 374337536 69143 18446744073709551615 4194304 6763684 140736000099552 140736000096504 140286614249178 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/27730/statm: 91391 69143 1070 628 0 67944 0 Current children cumulated CPU time (s) 6.27 Current children cumulated vsize (KiB) 365564 [startup+12.7002 s] /proc/loadavg: 0.93 0.98 0.99 2/54 27733 /proc/meminfo: memFree=116448/1022884 swapFree=0/0 [pid=27730] ppid=27729 vsize=365564 CPUtime=12.64 /proc/27730/stat : 27730 (smart) R 27729 27730 2806 34818 2806 4202496 98902 414 0 0 1241 23 0 0 20 0 1 0 16130491 374337536 69146 18446744073709551615 4194304 6763684 140736000099552 140736000096504 140286614249178 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/27730/statm: 91391 69146 1073 628 0 67944 0 Current children cumulated CPU time (s) 12.64 Current children cumulated vsize (KiB) 365564 [startup+25.5002 s] /proc/loadavg: 0.95 0.98 0.99 2/54 27733 /proc/meminfo: memFree=116448/1022884 swapFree=0/0 [pid=27730] ppid=27729 vsize=365564 CPUtime=25.39 /proc/27730/stat : 27730 (smart) R 27729 27730 2806 34818 2806 4202496 98903 414 0 0 2516 23 0 0 20 0 1 0 16130491 374337536 69146 18446744073709551615 4194304 6763684 140736000099552 140736000096504 140286614252862 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/27730/statm: 91391 69146 1073 628 0 67944 0 Current children cumulated CPU time (s) 25.39 Current children cumulated vsize (KiB) 365564 [startup+51.1002 s] /proc/loadavg: 0.96 0.98 0.99 2/54 27733 /proc/meminfo: memFree=116448/1022884 swapFree=0/0 [pid=27730] ppid=27729 vsize=365564 CPUtime=50.89 /proc/27730/stat : 27730 (smart) R 27729 27730 2806 34818 2806 4202496 98906 414 0 0 5066 23 0 0 20 0 1 0 16130491 374337536 69146 18446744073709551615 4194304 6763684 140736000099552 140736000096504 140286614249178 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/27730/statm: 91391 69146 1073 628 0 67944 0 Current children cumulated CPU time (s) 50.89 Current children cumulated vsize (KiB) 365564 [startup+102.3 s] /proc/loadavg: 0.98 0.98 0.99 2/54 27733 /proc/meminfo: memFree=116324/1022884 swapFree=0/0 [pid=27730] ppid=27729 vsize=365564 CPUtime=101.9 /proc/27730/stat : 27730 (smart) R 27729 27730 2806 34818 2806 4202496 98906 414 0 0 10167 23 0 0 20 0 1 0 16130491 374337536 69146 18446744073709551615 4194304 6763684 140736000099552 140736000096504 140286614249236 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/27730/statm: 91391 69146 1073 628 0 67944 0 Current children cumulated CPU time (s) 101.9 Current children cumulated vsize (KiB) 365564 [startup+162.3 s] /proc/loadavg: 0.99 0.98 0.99 2/54 27733 /proc/meminfo: memFree=116324/1022884 swapFree=0/0 [pid=27730] ppid=27729 vsize=365564 CPUtime=161.67 /proc/27730/stat : 27730 (smart) R 27729 27730 2806 34818 2806 4202496 98908 414 0 0 16144 23 0 0 20 0 1 0 16130491 374337536 69146 18446744073709551615 4194304 6763684 140736000099552 140736000096504 140286596501185 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/27730/statm: 91391 69146 1073 628 0 67944 0 Current children cumulated CPU time (s) 161.67 Current children cumulated vsize (KiB) 365564 [startup+222.303 s] /proc/loadavg: 0.99 0.98 0.99 2/54 27733 /proc/meminfo: memFree=116324/1022884 swapFree=0/0 [pid=27730] ppid=27729 vsize=365564 CPUtime=221.44 /proc/27730/stat : 27730 (smart) R 27729 27730 2806 34818 2806 4202496 98909 414 0 0 22121 23 0 0 20 0 1 0 16130491 374337536 69146 18446744073709551615 4194304 6763684 140736000099552 140736000096504 140286614249312 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/27730/statm: 91391 69146 1073 628 0 67944 0 Current children cumulated CPU time (s) 221.44 Current children cumulated vsize (KiB) 365564 [startup+282.3 s] /proc/loadavg: 0.99 0.98 0.99 2/54 27733 /proc/meminfo: memFree=116324/1022884 swapFree=0/0 [pid=27730] ppid=27729 vsize=365564 CPUtime=281.21 /proc/27730/stat : 27730 (smart) R 27729 27730 2806 34818 2806 4202496 98909 414 0 0 28098 23 0 0 20 0 1 0 16130491 374337536 69146 18446744073709551615 4194304 6763684 140736000099552 140736000096504 140286596501185 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/27730/statm: 91391 69146 1073 628 0 67944 0 Current children cumulated CPU time (s) 281.21 Current children cumulated vsize (KiB) 365564 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 0.99 0.98 0.99 2/54 27733 /proc/meminfo: memFree=116324/1022884 swapFree=0/0 [pid=27730] ppid=27729 vsize=365564 CPUtime=298.85 /proc/27730/stat : 27730 (smart) R 27729 27730 2806 34818 2806 4202496 98909 414 0 0 29862 23 0 0 20 0 1 0 16130491 374337536 69146 18446744073709551615 4194304 6763684 140736000099552 140736000096504 140286614249285 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/27730/statm: 91391 69146 1073 628 0 67944 0 Current children cumulated CPU time (s) 298.85 Current children cumulated vsize (KiB) 365564 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.99 2/54 27733 /proc/meminfo: memFree=116324/1022884 swapFree=0/0 [pid=27730] ppid=27729 vsize=365564 CPUtime=298.85 /proc/27730/stat : 27730 (smart) R 27729 27730 2806 34818 2806 4202496 98909 414 0 0 29862 23 0 0 20 0 1 0 16130491 374337536 69146 18446744073709551615 4194304 6763684 140736000099552 140736000096504 140286614249285 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/27730/statm: 91391 69146 1073 628 0 67944 0 Current children cumulated CPU time (s) 298.85 Current children cumulated vsize (KiB) 365564 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.026 CPU time (s): 298.883 CPU user time (s): 298.623 CPU system time (s): 0.260016 CPU usage (%): 99.6188 Max. virtual memory (cumulated for all children) (KiB): 365564 getrusage(RUSAGE_CHILDREN,...) data: user time used= 298.623 system time used= 0.260016 maximum resident set size= 276584 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 99323 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= 4341 runsolver used 0.32402 second user time and 0.824051 second system time The end