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: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand753.sarge-etch-lenny-squeeze-sid.cudf.sarge-etch-lenny-squeeze-sid.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/icse/sarge-etch-lenny-squeeze-sid/rand753.sarge-etch-lenny-squeeze-sid.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand753.sarge-etch-lenny-squeeze-sid.cudf.sarge-etch-lenny-squeeze-sid.result Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 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: 1.15 1.11 1.07 3/51 22442 /proc/meminfo: memFree=492976/1048576 swapFree=2075100/2097144 [pid=22440] ppid=22439 vsize=2588 CPUtime=0 /proc/22440/stat : 22440 (aspcud-trendy-1) S 22439 22440 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 882037731 2650112 282 1283457024 134512640 135304128 4290930160 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/22440/statm: 647 282 237 194 0 33 0 [pid=22441] ppid=22440 vsize=2588 CPUtime=0 /proc/22441/stat : 22441 (aspcud-trendy-1) R 22440 22440 4159 34819 4229 4202560 105 0 0 0 0 0 0 0 25 0 1 0 882037731 2650112 128 1283457024 134512640 135304128 4290930160 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/22441/statm: 647 128 82 194 0 33 0 [pid=22442] ppid=22441 vsize=2588 CPUtime=0 /proc/22442/stat : 22442 (aspcud-trendy-1) R 22441 22440 4159 34819 4229 4202560 0 0 0 0 0 0 0 0 25 0 1 0 882037731 2650112 46 1283457024 134512640 135304128 4290930160 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/22442/statm: 647 46 0 194 0 33 0 [startup+0.179964 s] /proc/loadavg: 1.15 1.11 1.07 3/51 22442 /proc/meminfo: memFree=492976/1048576 swapFree=2075100/2097144 [pid=22440] ppid=22439 vsize=2600 CPUtime=0.01 /proc/22440/stat : 22440 (aspcud-trendy-1) S 22439 22440 4159 34819 4229 4202496 626 2215 0 0 0 0 0 1 25 0 1 0 882037731 2662400 301 1283457024 134512640 135304128 4290930160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22440/statm: 650 301 253 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+0.209977 s] /proc/loadavg: 1.15 1.11 1.07 3/51 22442 /proc/meminfo: memFree=492976/1048576 swapFree=2075100/2097144 [pid=22440] ppid=22439 vsize=2600 CPUtime=0.01 /proc/22440/stat : 22440 (aspcud-trendy-1) S 22439 22440 4159 34819 4229 4202496 626 2215 0 0 0 0 0 1 25 0 1 0 882037731 2662400 301 1283457024 134512640 135304128 4290930160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22440/statm: 650 301 253 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+0.309996 s] /proc/loadavg: 1.15 1.11 1.07 3/51 22442 /proc/meminfo: memFree=492976/1048576 swapFree=2075100/2097144 [pid=22440] ppid=22439 vsize=2600 CPUtime=0.01 /proc/22440/stat : 22440 (aspcud-trendy-1) S 22439 22440 4159 34819 4229 4202496 626 2215 0 0 0 0 0 1 25 0 1 0 882037731 2662400 301 1283457024 134512640 135304128 4290930160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22440/statm: 650 301 253 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+0.710123 s] /proc/loadavg: 1.15 1.11 1.07 3/51 22442 /proc/meminfo: memFree=492976/1048576 swapFree=2075100/2097144 [pid=22440] ppid=22439 vsize=2600 CPUtime=0.01 /proc/22440/stat : 22440 (aspcud-trendy-1) S 22439 22440 4159 34819 4229 4202496 626 2215 0 0 0 0 0 1 25 0 1 0 882037731 2662400 301 1283457024 134512640 135304128 4290930160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22440/statm: 650 301 253 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+1.51031 s] /proc/loadavg: 1.15 1.11 1.07 2/53 22454 /proc/meminfo: memFree=451404/1048576 swapFree=2075100/2097144 [pid=22440] ppid=22439 vsize=2600 CPUtime=0.01 /proc/22440/stat : 22440 (aspcud-trendy-1) S 22439 22440 4159 34819 4229 4202496 626 2215 0 0 0 0 0 1 25 0 1 0 882037731 2662400 301 1283457024 134512640 135304128 4290930160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22440/statm: 650 301 253 194 0 36 0 [pid=22452] ppid=22440 vsize=4696 CPUtime=0 /proc/22452/stat : 22452 (clasp) S 22440 22440 4159 34819 4229 4202496 1031 0 0 0 0 0 0 0 18 0 1 0 882037733 4808704 898 1283457024 134512640 136223643 4293699760 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/22452/statm: 1174 898 174 418 0 754 0 [pid=22453] ppid=22440 vsize=6380 CPUtime=0.15 /proc/22453/stat : 22453 (gringo) S 22440 22440 4159 34819 4229 4202496 1533 0 0 0 15 0 0 0 18 0 1 0 882037733 6533120 1125 1283457024 134512640 136959103 4290774624 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/22453/statm: 1595 1125 247 598 0 994 0 [pid=22454] ppid=22440 vsize=45400 CPUtime=1.34 /proc/22454/stat : 22454 (cudf2lp) R 22440 22440 4159 34819 4229 4202496 14557 0 0 0 130 4 0 0 25 0 1 0 882037733 46489600 11145 1283457024 134512640 135749571 4288670848 18446744073709551615 134790473 0 0 6 0 0 0 0 17 0 0 0 0 /proc/22454/statm: 11350 11145 129 302 0 11046 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 59076 [startup+3.11061 s] /proc/loadavg: 1.15 1.11 1.07 3/53 22456 /proc/meminfo: memFree=421520/1048576 swapFree=2075100/2097144 [pid=22440] ppid=22439 vsize=2600 CPUtime=1.58 /proc/22440/stat : 22440 (aspcud-trendy-1) S 22439 22440 4159 34819 4229 4202496 627 16776 0 0 0 0 152 6 18 0 1 0 882037731 2662400 301 1283457024 134512640 135304128 4290930160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22440/statm: 650 301 253 194 0 36 0 [pid=22452] ppid=22440 vsize=30116 CPUtime=0.07 /proc/22452/stat : 22452 (clasp) R 22440 22440 4159 34819 4229 4202496 8754 0 0 0 6 1 0 0 18 0 1 0 882037733 30838784 6949 1283457024 134512640 136223643 4293699760 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/22452/statm: 7529 6949 174 418 0 7109 0 [pid=22453] ppid=22440 vsize=45704 CPUtime=1.4 /proc/22453/stat : 22453 (gringo) R 22440 22440 4159 34819 4229 4202496 13822 0 0 0 136 4 0 0 18 0 1 0 882037733 46800896 9495 1283457024 134512640 136959103 4290774624 18446744073709551615 135788230 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/22453/statm: 11426 9495 256 598 0 10825 0 Current children cumulated CPU time (s) 3.05 Current children cumulated vsize (KiB) 78420 [startup+6.31145 s] /proc/loadavg: 1.14 1.11 1.07 2/51 22458 /proc/meminfo: memFree=439036/1048576 swapFree=2075100/2097144 [pid=22440] ppid=22439 vsize=2600 CPUtime=3.73 /proc/22440/stat : 22440 (aspcud-trendy-1) S 22439 22440 4159 34819 4229 4202496 627 36008 0 0 0 0 360 13 18 0 1 0 882037731 2662400 301 1283457024 134512640 135304128 4290930160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22440/statm: 650 301 253 194 0 36 0 [pid=22452] ppid=22440 vsize=58396 CPUtime=2.5 /proc/22452/stat : 22452 (clasp) R 22440 22440 4159 34819 4229 4202496 16997 0 0 0 248 2 0 0 21 0 1 0 882037733 59797504 13486 1283457024 134512640 136223643 4293699760 18446744073709551615 134665182 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/22452/statm: 14599 13486 225 418 0 14179 0 Current children cumulated CPU time (s) 6.23 Current children cumulated vsize (KiB) 60996 [startup+12.7133 s] /proc/loadavg: 1.12 1.10 1.07 2/51 22462 /proc/meminfo: memFree=439656/1048576 swapFree=2075100/2097144 [pid=22440] ppid=22439 vsize=2600 CPUtime=3.73 /proc/22440/stat : 22440 (aspcud-trendy-1) S 22439 22440 4159 34819 4229 4202496 627 36008 0 0 0 0 360 13 18 0 1 0 882037731 2662400 301 1283457024 134512640 135304128 4290930160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22440/statm: 650 301 253 194 0 36 0 [pid=22452] ppid=22440 vsize=58396 CPUtime=8.86 /proc/22452/stat : 22452 (clasp) R 22440 22440 4159 34819 4229 4202496 17014 0 0 0 884 2 0 0 25 0 1 0 882037733 59797504 13503 1283457024 134512640 136223643 4293699760 18446744073709551615 134929384 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/22452/statm: 14599 13503 225 418 0 14179 0 Current children cumulated CPU time (s) 12.59 Current children cumulated vsize (KiB) 60996 [startup+25.5071 s] /proc/loadavg: 1.17 1.12 1.08 2/51 22468 /proc/meminfo: memFree=439416/1048576 swapFree=2075100/2097144 [pid=22440] ppid=22439 vsize=2600 CPUtime=3.73 /proc/22440/stat : 22440 (aspcud-trendy-1) S 22439 22440 4159 34819 4229 4202496 627 36008 0 0 0 0 360 13 18 0 1 0 882037731 2662400 301 1283457024 134512640 135304128 4290930160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22440/statm: 650 301 253 194 0 36 0 [pid=22452] ppid=22440 vsize=58396 CPUtime=21.59 /proc/22452/stat : 22452 (clasp) R 22440 22440 4159 34819 4229 4202496 17014 0 0 0 2155 4 0 0 25 0 1 0 882037733 59797504 13503 1283457024 134512640 136223643 4293699760 18446744073709551615 134931096 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/22452/statm: 14599 13503 225 418 0 14179 0 Current children cumulated CPU time (s) 25.32 Current children cumulated vsize (KiB) 60996 [startup+51.1033 s] /proc/loadavg: 1.11 1.11 1.07 2/51 22484 /proc/meminfo: memFree=390808/1048576 swapFree=2075100/2097144 [pid=22440] ppid=22439 vsize=2600 CPUtime=3.73 /proc/22440/stat : 22440 (aspcud-trendy-1) S 22439 22440 4159 34819 4229 4202496 627 36008 0 0 0 0 360 13 18 0 1 0 882037731 2662400 301 1283457024 134512640 135304128 4290930160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22440/statm: 650 301 253 194 0 36 0 [pid=22452] ppid=22440 vsize=110692 CPUtime=46.95 /proc/22452/stat : 22452 (clasp) R 22440 22440 4159 34819 4229 4202496 30085 0 0 0 4683 12 0 0 25 0 1 0 882037733 113348608 26574 1283457024 134512640 136223643 4293699760 18446744073709551615 134704907 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/22452/statm: 27673 26574 225 418 0 27253 0 Current children cumulated CPU time (s) 50.68 Current children cumulated vsize (KiB) 113292 [startup+102.307 s] /proc/loadavg: 1.10 1.10 1.08 2/51 22512 /proc/meminfo: memFree=360800/1048576 swapFree=2075108/2097144 [pid=22440] ppid=22439 vsize=2600 CPUtime=3.73 /proc/22440/stat : 22440 (aspcud-trendy-1) S 22439 22440 4159 34819 4229 4202496 627 36008 0 0 0 0 360 13 18 0 1 0 882037731 2662400 301 1283457024 134512640 135304128 4290930160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22440/statm: 650 301 253 194 0 36 0 [pid=22452] ppid=22440 vsize=136788 CPUtime=97.71 /proc/22452/stat : 22452 (clasp) R 22440 22440 4159 34819 4229 4202496 36785 0 0 0 9755 16 0 0 25 0 1 0 882037733 140070912 33092 1283457024 134512640 136223643 4293699760 18446744073709551615 134924290 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/22452/statm: 34197 33092 225 418 0 33777 0 Current children cumulated CPU time (s) 101.44 Current children cumulated vsize (KiB) 139388 [startup+162.312 s] /proc/loadavg: 1.13 1.11 1.08 2/48 22544 /proc/meminfo: memFree=284720/1048576 swapFree=2077704/2097144 [pid=22440] ppid=22439 vsize=2600 CPUtime=3.73 /proc/22440/stat : 22440 (aspcud-trendy-1) S 22439 22440 4159 34819 4229 4202496 627 36008 0 0 0 0 360 13 18 0 1 0 882037731 2662400 301 1283457024 134512640 135304128 4290930160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22440/statm: 650 301 253 194 0 36 0 [pid=22452] ppid=22440 vsize=212816 CPUtime=157.22 /proc/22452/stat : 22452 (clasp) R 22440 22440 4159 34819 4229 4202496 55775 0 0 0 15698 24 0 0 25 0 1 0 882037733 217923584 52082 1283457024 134512640 136223643 4293699760 18446744073709551615 134711782 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/22452/statm: 53204 52082 225 418 0 52784 0 Current children cumulated CPU time (s) 160.95 Current children cumulated vsize (KiB) 215416 [startup+222.308 s] /proc/loadavg: 1.05 1.09 1.07 2/48 22578 /proc/meminfo: memFree=245412/1048576 swapFree=2077704/2097144 [pid=22440] ppid=22439 vsize=2600 CPUtime=3.73 /proc/22440/stat : 22440 (aspcud-trendy-1) S 22439 22440 4159 34819 4229 4202496 627 36008 0 0 0 0 360 13 18 0 1 0 882037731 2662400 301 1283457024 134512640 135304128 4290930160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22440/statm: 650 301 253 194 0 36 0 [pid=22452] ppid=22440 vsize=252100 CPUtime=216.75 /proc/22452/stat : 22452 (clasp) R 22440 22440 4159 34819 4229 4202496 65567 0 0 0 21649 26 0 0 25 0 1 0 882037733 258150400 61874 1283457024 134512640 136223643 4293699760 18446744073709551615 134704885 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/22452/statm: 63025 61874 225 418 0 62605 0 Current children cumulated CPU time (s) 220.48 Current children cumulated vsize (KiB) 254700 [startup+282.313 s] /proc/loadavg: 1.02 1.07 1.07 2/48 22612 /proc/meminfo: memFree=174980/1048576 swapFree=2077704/2097144 [pid=22440] ppid=22439 vsize=2600 CPUtime=3.73 /proc/22440/stat : 22440 (aspcud-trendy-1) S 22439 22440 4159 34819 4229 4202496 627 36008 0 0 0 0 360 13 18 0 1 0 882037731 2662400 301 1283457024 134512640 135304128 4290930160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22440/statm: 650 301 253 194 0 36 0 [pid=22452] ppid=22440 vsize=322424 CPUtime=276.21 /proc/22452/stat : 22452 (clasp) R 22440 22440 4159 34819 4229 4202496 83138 0 0 0 27580 41 0 0 25 0 1 0 882037733 330162176 79445 1283457024 134512640 136223643 4293699760 18446744073709551615 134928992 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/22452/statm: 80606 79445 225 418 0 80186 0 Current children cumulated CPU time (s) 279.94 Current children cumulated vsize (KiB) 325024 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+292.506 s] /proc/loadavg: 1.01 1.07 1.07 2/48 22618 /proc/meminfo: memFree=174856/1048576 swapFree=2077704/2097144 [pid=22440] ppid=22439 vsize=2600 CPUtime=3.73 /proc/22440/stat : 22440 (aspcud-trendy-1) S 22439 22440 4159 34819 4229 4202496 627 36008 0 0 0 0 360 13 18 0 1 0 882037731 2662400 301 1283457024 134512640 135304128 4290930160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22440/statm: 650 301 253 194 0 36 0 [pid=22452] ppid=22440 vsize=322424 CPUtime=286.32 /proc/22452/stat : 22452 (clasp) R 22440 22440 4159 34819 4229 4202496 83142 0 0 0 28591 41 0 0 25 0 1 0 882037733 330162176 79449 1283457024 134512640 136223643 4293699760 18446744073709551615 134704895 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/22452/statm: 80606 79449 225 418 0 80186 0 Current children cumulated CPU time (s) 290.05 Current children cumulated vsize (KiB) 325024 Sending User defined signal 1 to process tree (bottom up) Sleeping 10 seconds Solver just ended. Dumping a history of the last processes samples Child status: 0 Real time (s): 292.546 CPU time (s): 290.09 CPU user time (s): 289.522 CPU system time (s): 0.568035 CPU usage (%): 99.1606 Max. virtual memory (cumulated for all children) (KiB): 325024 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.522 system time used= 0.568035 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 122391 page faults= 1 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 2967 involuntary context switches= 7205 runsolver used 0 second user time and 0 second system time The end