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/rand550.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/rand550.sarge-etch-lenny-squeeze-sid.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand550.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.19 1.15 1.10 1/43 19798 /proc/meminfo: memFree=773976/1048576 swapFree=2077680/2097144 [pid=19798] ppid=19797 vsize=3024 CPUtime=0 /proc/19798/stat : 19798 (runsolver) R 19797 19798 4159 34819 4229 4202560 73 0 0 0 0 0 0 0 25 0 1 0 881453583 3096576 94 1283457024 134512640 134586868 4291200320 18446744073709551615 4294960130 0 0 0 24578 0 0 0 17 0 0 0 0 /proc/19798/statm: 756 94 62 19 0 54 0 [startup+0.15927 s] /proc/loadavg: 1.19 1.15 1.10 1/43 19798 /proc/meminfo: memFree=773976/1048576 swapFree=2077680/2097144 [pid=19798] ppid=19797 vsize=2600 CPUtime=0 /proc/19798/stat : 19798 (aspcud-trendy-1) S 19797 19798 4159 34819 4229 4202496 625 2213 1 3 0 0 0 0 25 0 1 0 881453583 2662400 301 1283457024 134512640 135304128 4289594544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19798/statm: 650 301 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.20727 s] /proc/loadavg: 1.19 1.15 1.10 1/43 19798 /proc/meminfo: memFree=773976/1048576 swapFree=2077680/2097144 [pid=19798] ppid=19797 vsize=2600 CPUtime=0 /proc/19798/stat : 19798 (aspcud-trendy-1) S 19797 19798 4159 34819 4229 4202496 625 2213 1 3 0 0 0 0 25 0 1 0 881453583 2662400 301 1283457024 134512640 135304128 4289594544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19798/statm: 650 301 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.307267 s] /proc/loadavg: 1.19 1.15 1.10 1/43 19798 /proc/meminfo: memFree=773976/1048576 swapFree=2077680/2097144 [pid=19798] ppid=19797 vsize=2600 CPUtime=0 /proc/19798/stat : 19798 (aspcud-trendy-1) S 19797 19798 4159 34819 4229 4202496 625 2213 1 3 0 0 0 0 25 0 1 0 881453583 2662400 301 1283457024 134512640 135304128 4289594544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19798/statm: 650 301 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.70822 s] /proc/loadavg: 1.19 1.15 1.10 1/43 19798 /proc/meminfo: memFree=773976/1048576 swapFree=2077680/2097144 [pid=19798] ppid=19797 vsize=2600 CPUtime=0 /proc/19798/stat : 19798 (aspcud-trendy-1) S 19797 19798 4159 34819 4229 4202496 625 2213 1 3 0 0 0 0 25 0 1 0 881453583 2662400 301 1283457024 134512640 135304128 4289594544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19798/statm: 650 301 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+1.50839 s] /proc/loadavg: 1.18 1.15 1.10 2/47 19812 /proc/meminfo: memFree=736408/1048576 swapFree=2077680/2097144 [pid=19798] ppid=19797 vsize=2600 CPUtime=0 /proc/19798/stat : 19798 (aspcud-trendy-1) S 19797 19798 4159 34819 4229 4202496 625 2213 1 3 0 0 0 0 25 0 1 0 881453583 2662400 301 1283457024 134512640 135304128 4289594544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19798/statm: 650 301 253 194 0 36 0 [pid=19810] ppid=19798 vsize=1868 CPUtime=0 /proc/19810/stat : 19810 (clasp) S 19798 19798 4159 34819 4229 4202496 269 0 16 0 0 0 0 0 23 0 1 0 881453588 1912832 152 1283457024 134512640 136223643 4288822320 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/19810/statm: 467 152 138 418 0 47 0 [pid=19811] ppid=19798 vsize=2608 CPUtime=0 /proc/19811/stat : 19811 (gringo) S 19798 19798 4159 34819 4229 4202496 386 0 23 0 0 0 0 0 23 0 1 0 881453588 2670592 277 1283457024 134512640 136959103 4289189120 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/19811/statm: 652 277 247 598 0 51 0 [pid=19812] ppid=19798 vsize=45400 CPUtime=1.23 /proc/19812/stat : 19812 (cudf2lp) R 19798 19798 4159 34819 4229 4202496 14540 0 15 0 117 6 0 0 25 0 1 0 881453588 46489600 11143 1283457024 134512640 135749571 4288825584 18446744073709551615 135170557 0 0 6 0 0 0 0 17 0 0 0 0 /proc/19812/statm: 11350 11143 127 302 0 11046 0 Current children cumulated CPU time (s) 1.23 Current children cumulated vsize (KiB) 52476 [startup+3.11091 s] /proc/loadavg: 1.18 1.15 1.10 2/47 19812 /proc/meminfo: memFree=703804/1048576 swapFree=2077680/2097144 [pid=19798] ppid=19797 vsize=2600 CPUtime=1.66 /proc/19798/stat : 19798 (aspcud-trendy-1) S 19797 19798 4159 34819 4229 4202496 626 16759 1 19 0 0 156 10 18 0 1 0 881453583 2662400 301 1283457024 134512640 135304128 4289594544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19798/statm: 650 301 253 194 0 36 0 [pid=19810] ppid=19798 vsize=25080 CPUtime=0.09 /proc/19810/stat : 19810 (clasp) R 19798 19798 4159 34819 4229 4202496 7090 0 19 0 8 1 0 0 18 0 1 0 881453588 25681920 5912 1283457024 134512640 136223643 4288822320 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19810/statm: 6270 5912 174 418 0 5850 0 [pid=19811] ppid=19798 vsize=38624 CPUtime=1.07 /proc/19811/stat : 19811 (gringo) R 19798 19798 4159 34819 4229 4202496 11720 0 23 0 105 2 0 0 18 0 1 0 881453588 39550976 7802 1283457024 134512640 136959103 4289189120 18446744073709551615 135865912 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19811/statm: 9656 7802 256 598 0 9055 0 Current children cumulated CPU time (s) 2.82 Current children cumulated vsize (KiB) 66304 [startup+6.30421 s] /proc/loadavg: 1.24 1.16 1.10 2/45 19812 /proc/meminfo: memFree=714068/1048576 swapFree=2077680/2097144 [pid=19798] ppid=19797 vsize=2600 CPUtime=3.66 /proc/19798/stat : 19798 (aspcud-trendy-1) S 19797 19798 4159 34819 4229 4202496 626 35977 1 42 0 0 350 16 18 0 1 0 881453583 2662400 301 1283457024 134512640 135304128 4289594544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19798/statm: 650 301 253 194 0 36 0 [pid=19810] ppid=19798 vsize=58632 CPUtime=2.34 /proc/19810/stat : 19810 (clasp) R 19798 19798 4159 34819 4229 4202496 17236 0 20 0 229 5 0 0 20 0 1 0 881453588 60039168 13558 1283457024 134512640 136223643 4288822320 18446744073709551615 134870708 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19810/statm: 14658 13558 223 418 0 14238 0 Current children cumulated CPU time (s) 6 Current children cumulated vsize (KiB) 61232 [startup+12.706 s] /proc/loadavg: 1.22 1.16 1.10 2/45 19812 /proc/meminfo: memFree=714812/1048576 swapFree=2077680/2097144 [pid=19798] ppid=19797 vsize=2600 CPUtime=3.66 /proc/19798/stat : 19798 (aspcud-trendy-1) S 19797 19798 4159 34819 4229 4202496 626 35977 1 42 0 0 350 16 18 0 1 0 881453583 2662400 301 1283457024 134512640 135304128 4289594544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19798/statm: 650 301 253 194 0 36 0 [pid=19810] ppid=19798 vsize=60912 CPUtime=8.73 /proc/19810/stat : 19810 (clasp) R 19798 19798 4159 34819 4229 4202496 17810 0 20 0 868 5 0 0 25 0 1 0 881453588 62373888 14132 1283457024 134512640 136223643 4288822320 18446744073709551615 134711224 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19810/statm: 15228 14132 225 418 0 14808 0 Current children cumulated CPU time (s) 12.39 Current children cumulated vsize (KiB) 63512 [startup+25.5097 s] /proc/loadavg: 1.17 1.15 1.10 2/45 19812 /proc/meminfo: memFree=677116/1048576 swapFree=2077680/2097144 [pid=19798] ppid=19797 vsize=2600 CPUtime=3.66 /proc/19798/stat : 19798 (aspcud-trendy-1) S 19797 19798 4159 34819 4229 4202496 626 35977 1 42 0 0 350 16 18 0 1 0 881453583 2662400 301 1283457024 134512640 135304128 4289594544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19798/statm: 650 301 253 194 0 36 0 [pid=19810] ppid=19798 vsize=96728 CPUtime=21.52 /proc/19810/stat : 19810 (clasp) R 19798 19798 4159 34819 4229 4202496 26755 0 20 0 2144 8 0 0 25 0 1 0 881453588 99049472 23077 1283457024 134512640 136223643 4288822320 18446744073709551615 134711229 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19810/statm: 24182 23077 225 418 0 23762 0 Current children cumulated CPU time (s) 25.18 Current children cumulated vsize (KiB) 99328 [startup+51.1064 s] /proc/loadavg: 1.11 1.14 1.09 2/45 19812 /proc/meminfo: memFree=661120/1048576 swapFree=2077680/2097144 [pid=19798] ppid=19797 vsize=2600 CPUtime=3.66 /proc/19798/stat : 19798 (aspcud-trendy-1) S 19797 19798 4159 34819 4229 4202496 626 35977 1 42 0 0 350 16 18 0 1 0 881453583 2662400 301 1283457024 134512640 135304128 4289594544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19798/statm: 650 301 253 194 0 36 0 [pid=19810] ppid=19798 vsize=112652 CPUtime=47.11 /proc/19810/stat : 19810 (clasp) R 19798 19798 4159 34819 4229 4202496 30706 0 20 0 4697 14 0 0 25 0 1 0 881453588 115355648 27028 1283457024 134512640 136223643 4288822320 18446744073709551615 134711295 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19810/statm: 28163 27028 225 418 0 27743 0 Current children cumulated CPU time (s) 50.77 Current children cumulated vsize (KiB) 115252 [startup+102.303 s] /proc/loadavg: 1.05 1.11 1.09 2/45 19812 /proc/meminfo: memFree=565640/1048576 swapFree=2077680/2097144 [pid=19798] ppid=19797 vsize=2600 CPUtime=3.66 /proc/19798/stat : 19798 (aspcud-trendy-1) S 19797 19798 4159 34819 4229 4202496 626 35977 1 42 0 0 350 16 18 0 1 0 881453583 2662400 301 1283457024 134512640 135304128 4289594544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19798/statm: 650 301 253 194 0 36 0 [pid=19810] ppid=19798 vsize=208084 CPUtime=98.19 /proc/19810/stat : 19810 (clasp) R 19798 19798 4159 34819 4229 4202496 54534 0 20 0 9790 29 0 0 25 0 1 0 881453588 213078016 50856 1283457024 134512640 136223643 4288822320 18446744073709551615 134713010 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19810/statm: 52021 50856 225 418 0 51601 0 Current children cumulated CPU time (s) 101.85 Current children cumulated vsize (KiB) 210684 [startup+162.312 s] /proc/loadavg: 1.02 1.09 1.08 2/45 19812 /proc/meminfo: memFree=458256/1048576 swapFree=2077680/2097144 [pid=19798] ppid=19797 vsize=2600 CPUtime=3.66 /proc/19798/stat : 19798 (aspcud-trendy-1) S 19797 19798 4159 34819 4229 4202496 626 35977 1 42 0 0 350 16 18 0 1 0 881453583 2662400 301 1283457024 134512640 135304128 4289594544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19798/statm: 650 301 253 194 0 36 0 [pid=19810] ppid=19798 vsize=315304 CPUtime=158.15 /proc/19810/stat : 19810 (clasp) R 19798 19798 4159 34819 4229 4202496 81322 0 20 0 15764 51 0 0 25 0 1 0 881453588 322871296 77644 1283457024 134512640 136223643 4288822320 18446744073709551615 134711282 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19810/statm: 78826 77644 225 418 0 78406 0 Current children cumulated CPU time (s) 161.81 Current children cumulated vsize (KiB) 317904 [startup+222.315 s] /proc/loadavg: 1.00 1.07 1.08 2/45 19812 /proc/meminfo: memFree=405556/1048576 swapFree=2077680/2097144 [pid=19798] ppid=19797 vsize=2600 CPUtime=3.66 /proc/19798/stat : 19798 (aspcud-trendy-1) S 19797 19798 4159 34819 4229 4202496 626 35977 1 42 0 0 350 16 18 0 1 0 881453583 2662400 301 1283457024 134512640 135304128 4289594544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19798/statm: 650 301 253 194 0 36 0 [pid=19810] ppid=19798 vsize=368208 CPUtime=218.08 /proc/19810/stat : 19810 (clasp) R 19798 19798 4159 34819 4229 4202496 94648 0 20 0 21742 66 0 0 25 0 1 0 881453588 377044992 90865 1283457024 134512640 136223643 4288822320 18446744073709551615 134931110 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19810/statm: 92052 90865 225 418 0 91632 0 Current children cumulated CPU time (s) 221.74 Current children cumulated vsize (KiB) 370808 [startup+282.305 s] /proc/loadavg: 1.00 1.06 1.07 2/45 19812 /proc/meminfo: memFree=326196/1048576 swapFree=2077680/2097144 [pid=19798] ppid=19797 vsize=2600 CPUtime=3.66 /proc/19798/stat : 19798 (aspcud-trendy-1) S 19797 19798 4159 34819 4229 4202496 626 35977 1 42 0 0 350 16 18 0 1 0 881453583 2662400 301 1283457024 134512640 135304128 4289594544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19798/statm: 650 301 253 194 0 36 0 [pid=19810] ppid=19798 vsize=447172 CPUtime=278.02 /proc/19810/stat : 19810 (clasp) R 19798 19798 4159 34819 4229 4202496 114511 0 20 0 27716 86 0 0 25 0 1 0 881453588 457904128 110592 1283457024 134512640 136223643 4288822320 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19810/statm: 111793 110592 225 418 0 111373 0 Current children cumulated CPU time (s) 281.68 Current children cumulated vsize (KiB) 449772 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.708 s] /proc/loadavg: 1.00 1.05 1.07 2/45 19812 /proc/meminfo: memFree=326196/1048576 swapFree=2077680/2097144 [pid=19798] ppid=19797 vsize=2600 CPUtime=3.66 /proc/19798/stat : 19798 (aspcud-trendy-1) S 19797 19798 4159 34819 4229 4202496 626 35977 1 42 0 0 350 16 18 0 1 0 881453583 2662400 301 1283457024 134512640 135304128 4289594544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19798/statm: 650 301 253 194 0 36 0 [pid=19810] ppid=19798 vsize=447172 CPUtime=286.43 /proc/19810/stat : 19810 (clasp) R 19798 19798 4159 34819 4229 4202496 114511 0 20 0 28557 86 0 0 25 0 1 0 881453588 457904128 110592 1283457024 134512640 136223643 4288822320 18446744073709551615 134929364 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19810/statm: 111793 110592 225 418 0 111373 0 Current children cumulated CPU time (s) 290.09 Current children cumulated vsize (KiB) 449772 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): 290.779 CPU time (s): 290.138 CPU user time (s): 289.078 CPU system time (s): 1.06007 CPU usage (%): 99.7795 Max. virtual memory (cumulated for all children) (KiB): 449772 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.078 system time used= 1.06007 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 153724 page faults= 65 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 3024 involuntary context switches= 5781 runsolver used 0.004 second user time and 0 second system time The end