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/logs/76.runsolver.smart smart --config-file=/home/cbse/var/lib/smart/config install python2.4-reportlab quack-el acl2-books-certs steptalk curl 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.98 0.99 2/53 20585 /proc/meminfo: memFree=362020/1022884 swapFree=0/0 [pid=20585] ppid=20584 vsize=3152 CPUtime=0 /proc/20585/stat : 20585 (runsolver) R 20584 2806 2806 34818 2806 4202560 0 0 0 0 0 0 0 0 20 0 1 0 11625548 3227648 32 18446744073709551615 134512640 134586868 4287691280 4287689328 4151452720 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/20585/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.123239 s] /proc/loadavg: 0.99 0.98 0.99 2/53 20585 /proc/meminfo: memFree=362020/1022884 swapFree=0/0 [pid=20585] ppid=20584 vsize=113488 CPUtime=0.12 /proc/20585/stat : 20585 (smart) R 20584 20585 2806 34818 2806 4202496 8385 0 0 0 8 4 0 0 20 0 1 0 11625548 116211712 7105 18446744073709551615 4194304 6763684 140733713099472 140733713094552 140026953226670 0 0 16781312 2 0 0 0 17 0 0 0 0 0 0 /proc/20585/statm: 28372 7105 1043 628 0 5955 0 Current children cumulated CPU time (s) 0.12 Current children cumulated vsize (KiB) 113488 [startup+0.200262 s] /proc/loadavg: 0.99 0.98 0.99 2/53 20585 /proc/meminfo: memFree=362020/1022884 swapFree=0/0 [pid=20585] ppid=20584 vsize=130928 CPUtime=0.19 /proc/20585/stat : 20585 (smart) R 20584 20585 2806 34818 2806 4202496 14309 0 0 0 14 5 0 0 20 0 1 0 11625548 134070272 11492 18446744073709551615 4194304 6763684 140733713099472 140733713094472 140026953226653 0 0 16781312 2 0 0 0 17 0 0 0 0 0 0 /proc/20585/statm: 32732 11492 1043 628 0 10315 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 130928 [startup+0.300246 s] /proc/loadavg: 0.99 0.98 0.99 2/53 20585 /proc/meminfo: memFree=362020/1022884 swapFree=0/0 [pid=20585] ppid=20584 vsize=135824 CPUtime=0.28 /proc/20585/stat : 20585 (smart) R 20584 20585 2806 34818 2806 4202496 19081 410 0 0 20 8 0 0 20 0 1 0 11625548 139083776 11728 18446744073709551615 4194304 6763684 140733713099472 140733713095464 5763084 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/20585/statm: 33956 11728 1058 628 0 10509 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 135824 [startup+0.700208 s] /proc/loadavg: 0.99 0.98 0.99 2/53 20585 /proc/meminfo: memFree=362020/1022884 swapFree=0/0 [pid=20585] ppid=20584 vsize=182088 CPUtime=0.69 /proc/20585/stat : 20585 (smart) R 20584 20585 2806 34818 2806 4202496 34274 410 0 0 56 13 0 0 20 0 1 0 11625548 186458112 23231 18446744073709551615 4194304 6763684 140733713099472 140733713095528 140026953295269 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/20585/statm: 45522 23231 1059 628 0 22075 0 Current children cumulated CPU time (s) 0.69 Current children cumulated vsize (KiB) 182088 [startup+1.5002 s] /proc/loadavg: 0.99 0.98 0.99 2/54 20588 /proc/meminfo: memFree=225116/1022884 swapFree=0/0 [pid=20585] ppid=20584 vsize=285840 CPUtime=1.48 /proc/20585/stat : 20585 (smart) R 20584 20585 2806 34818 2806 4202496 66389 410 0 0 128 20 0 0 20 0 1 0 11625548 292700160 49198 18446744073709551615 4194304 6763684 140733713099472 140733713095464 5511864 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/20585/statm: 71460 49198 1059 628 0 48013 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 285840 [startup+3.1002 s] /proc/loadavg: 0.99 0.98 0.99 2/54 20588 /proc/meminfo: memFree=159272/1022884 swapFree=0/0 [pid=20585] ppid=20584 vsize=334360 CPUtime=3.07 /proc/20585/stat : 20585 (smart) R 20584 20585 2806 34818 2806 4202496 90800 410 0 0 278 29 0 0 20 0 1 0 11625548 342384640 61288 18446744073709551615 4194304 6763684 140733713099472 140733713095512 5749259 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/20585/statm: 83590 61288 1068 628 0 60143 0 Current children cumulated CPU time (s) 3.07 Current children cumulated vsize (KiB) 334360 [startup+6.3002 s] /proc/loadavg: 0.99 0.98 0.99 2/54 20588 /proc/meminfo: memFree=111284/1022884 swapFree=0/0 [pid=20585] ppid=20584 vsize=343328 CPUtime=6.26 /proc/20585/stat : 20585 (smart) R 20584 20585 2806 34818 2806 4202496 93113 410 0 0 597 29 0 0 20 0 1 0 11625548 351567872 63590 18446744073709551615 4194304 6763684 140733713099472 140733713096424 140026953916122 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/20585/statm: 85832 63590 1073 628 0 62385 0 Current children cumulated CPU time (s) 6.26 Current children cumulated vsize (KiB) 343328 [startup+12.7002 s] /proc/loadavg: 0.99 0.98 0.99 2/54 20588 /proc/meminfo: memFree=111160/1022884 swapFree=0/0 [pid=20585] ppid=20584 vsize=343328 CPUtime=12.63 /proc/20585/stat : 20585 (smart) R 20584 20585 2806 34818 2806 4202496 93113 410 0 0 1234 29 0 0 20 0 1 0 11625548 351567872 63590 18446744073709551615 4194304 6763684 140733713099472 140733713096424 140026953919804 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/20585/statm: 85832 63590 1073 628 0 62385 0 Current children cumulated CPU time (s) 12.63 Current children cumulated vsize (KiB) 343328 [startup+25.5002 s] /proc/loadavg: 0.99 0.98 0.99 2/54 20588 /proc/meminfo: memFree=111160/1022884 swapFree=0/0 [pid=20585] ppid=20584 vsize=343328 CPUtime=25.38 /proc/20585/stat : 20585 (smart) R 20584 20585 2806 34818 2806 4202496 93113 410 0 0 2509 29 0 0 20 0 1 0 11625548 351567872 63590 18446744073709551615 4194304 6763684 140733713099472 140733713096424 140026953916256 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/20585/statm: 85832 63590 1073 628 0 62385 0 Current children cumulated CPU time (s) 25.38 Current children cumulated vsize (KiB) 343328 [startup+51.1002 s] /proc/loadavg: 0.99 0.98 0.99 2/54 20588 /proc/meminfo: memFree=111160/1022884 swapFree=0/0 [pid=20585] ppid=20584 vsize=343328 CPUtime=50.88 /proc/20585/stat : 20585 (smart) R 20584 20585 2806 34818 2806 4202496 93121 410 0 0 5059 29 0 0 20 0 1 0 11625548 351567872 63590 18446744073709551615 4194304 6763684 140733713099472 140733713096424 140026936168129 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/20585/statm: 85832 63590 1073 628 0 62385 0 Current children cumulated CPU time (s) 50.88 Current children cumulated vsize (KiB) 343328 [startup+102.3 s] /proc/loadavg: 0.99 0.98 0.99 2/54 20588 /proc/meminfo: memFree=111036/1022884 swapFree=0/0 [pid=20585] ppid=20584 vsize=343328 CPUtime=101.89 /proc/20585/stat : 20585 (smart) R 20584 20585 2806 34818 2806 4202496 93121 410 0 0 10160 29 0 0 20 0 1 0 11625548 351567872 63590 18446744073709551615 4194304 6763684 140733713099472 140733713096424 140026953916256 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/20585/statm: 85832 63590 1073 628 0 62385 0 Current children cumulated CPU time (s) 101.89 Current children cumulated vsize (KiB) 343328 [startup+162.3 s] /proc/loadavg: 0.99 0.98 0.99 2/54 20588 /proc/meminfo: memFree=109920/1022884 swapFree=0/0 [pid=20585] ppid=20584 vsize=344336 CPUtime=161.66 /proc/20585/stat : 20585 (smart) R 20584 20585 2806 34818 2806 4202496 93397 410 0 0 16137 29 0 0 20 0 1 0 11625548 352600064 63866 18446744073709551615 4194304 6763684 140733713099472 140733713016440 140026953916256 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/20585/statm: 86084 63866 1073 628 0 62637 0 Current children cumulated CPU time (s) 161.66 Current children cumulated vsize (KiB) 344336 [startup+222.303 s] /proc/loadavg: 0.99 0.98 0.99 2/54 20588 /proc/meminfo: memFree=109672/1022884 swapFree=0/0 [pid=20585] ppid=20584 vsize=344624 CPUtime=221.42 /proc/20585/stat : 20585 (smart) R 20584 20585 2806 34818 2806 4202496 93469 410 0 0 22113 29 0 0 20 0 1 0 11625548 352894976 63938 18446744073709551615 4194304 6763684 140733713099472 140733713016440 140026953916256 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/20585/statm: 86156 63938 1073 628 0 62709 0 Current children cumulated CPU time (s) 221.42 Current children cumulated vsize (KiB) 344624 [startup+282.3 s] /proc/loadavg: 0.99 0.98 0.99 2/54 20588 /proc/meminfo: memFree=109300/1022884 swapFree=0/0 [pid=20585] ppid=20584 vsize=345104 CPUtime=281.19 /proc/20585/stat : 20585 (smart) R 20584 20585 2806 34818 2806 4202496 93577 410 0 0 28090 29 0 0 20 0 1 0 11625548 353386496 64046 18446744073709551615 4194304 6763684 140733713099472 140733713024168 140026936168129 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/20585/statm: 86276 64046 1073 628 0 62829 0 Current children cumulated CPU time (s) 281.19 Current children cumulated vsize (KiB) 345104 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 0.99 0.98 0.99 2/54 20588 /proc/meminfo: memFree=109300/1022884 swapFree=0/0 [pid=20585] ppid=20584 vsize=345104 CPUtime=298.82 /proc/20585/stat : 20585 (smart) R 20584 20585 2806 34818 2806 4202496 93577 410 0 0 29853 29 0 0 20 0 1 0 11625548 353386496 64046 18446744073709551615 4194304 6763684 140733713099472 140733713024168 140026936168129 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/20585/statm: 86276 64046 1073 628 0 62829 0 Current children cumulated CPU time (s) 298.82 Current children cumulated vsize (KiB) 345104 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 20588 /proc/meminfo: memFree=109300/1022884 swapFree=0/0 [pid=20585] ppid=20584 vsize=345104 CPUtime=298.82 /proc/20585/stat : 20585 (smart) R 20584 20585 2806 34818 2806 4202496 93577 410 0 0 29853 29 0 0 20 0 1 0 11625548 353386496 64046 18446744073709551615 4194304 6763684 140733713099472 140733713024168 140026936168129 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/20585/statm: 86276 64046 1073 628 0 62829 0 Current children cumulated CPU time (s) 298.82 Current children cumulated vsize (KiB) 345104 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.028 CPU time (s): 298.863 CPU user time (s): 298.543 CPU system time (s): 0.32002 CPU usage (%): 99.6117 Max. virtual memory (cumulated for all children) (KiB): 345104 getrusage(RUSAGE_CHILDREN,...) data: user time used= 298.543 system time used= 0.32002 maximum resident set size= 256184 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 93987 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= 4376 runsolver used 0.304019 second user time and 0.864054 second system time The end