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/rand180.sarge.cudf.sarge.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/icse/sarge/rand180.sarge.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand180.sarge.cudf.sarge.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.07 1.02 1.01 5/43 13114 /proc/meminfo: memFree=826536/1048576 swapFree=2076380/2097144 [pid=13111] ppid=13110 vsize=2584 CPUtime=0 /proc/13111/stat : 13111 (aspcud-trendy-1) S 13110 13111 4159 34819 4229 4202496 374 0 0 0 0 0 0 0 18 0 1 0 879657394 2646016 281 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/13111/statm: 646 281 237 194 0 32 0 [pid=13112] ppid=13111 vsize=2584 CPUtime=0 /proc/13112/stat : 13112 (aspcud-trendy-1) S 13111 13111 4159 34819 4229 4202560 113 0 0 0 0 0 0 0 18 0 1 0 879657395 2646016 128 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/13112/statm: 646 128 83 194 0 32 0 [pid=13113] ppid=13112 vsize=2584 CPUtime=0 /proc/13113/stat : 13113 (aspcud-trendy-1) R 13112 13111 4159 34819 4229 4202560 126 0 0 0 0 0 0 0 25 0 1 0 879657395 2646016 148 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/13113/statm: 646 148 103 194 0 32 0 [pid=13114] ppid=13113 vsize=2584 CPUtime=0 /proc/13114/stat : 13114 (aspcud-trendy-1) R 13113 13111 4159 34819 4229 4202560 0 0 0 0 0 0 0 0 25 0 1 0 879657395 2646016 45 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/13114/statm: 646 45 0 194 0 32 0 [startup+0.127864 s] /proc/loadavg: 1.07 1.02 1.01 5/43 13114 /proc/meminfo: memFree=826536/1048576 swapFree=2076380/2097144 [pid=13111] ppid=13110 vsize=2596 CPUtime=0 /proc/13111/stat : 13111 (aspcud-trendy-1) S 13110 13111 4159 34819 4229 4202496 617 2220 0 0 0 0 0 0 25 0 1 0 879657394 2658304 300 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13111/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.207898 s] /proc/loadavg: 1.07 1.02 1.01 5/43 13114 /proc/meminfo: memFree=826536/1048576 swapFree=2076380/2097144 [pid=13111] ppid=13110 vsize=2596 CPUtime=0 /proc/13111/stat : 13111 (aspcud-trendy-1) S 13110 13111 4159 34819 4229 4202496 617 2220 0 0 0 0 0 0 25 0 1 0 879657394 2658304 300 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13111/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.307909 s] /proc/loadavg: 1.07 1.02 1.01 5/43 13114 /proc/meminfo: memFree=826536/1048576 swapFree=2076380/2097144 [pid=13111] ppid=13110 vsize=2596 CPUtime=0 /proc/13111/stat : 13111 (aspcud-trendy-1) S 13110 13111 4159 34819 4229 4202496 617 2220 0 0 0 0 0 0 25 0 1 0 879657394 2658304 300 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13111/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.708044 s] /proc/loadavg: 1.07 1.02 1.01 5/43 13114 /proc/meminfo: memFree=826536/1048576 swapFree=2076380/2097144 [pid=13111] ppid=13110 vsize=2596 CPUtime=0.52 /proc/13111/stat : 13111 (aspcud-trendy-1) S 13110 13111 4159 34819 4229 4202496 617 8462 0 0 0 0 50 2 21 0 1 0 879657394 2658304 300 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13111/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0.52 Current children cumulated vsize (KiB) 2596 [startup+1.50824 s] /proc/loadavg: 1.07 1.02 1.00 2/42 13125 /proc/meminfo: memFree=818224/1048576 swapFree=2076380/2097144 [pid=13111] ppid=13110 vsize=2596 CPUtime=0.52 /proc/13111/stat : 13111 (aspcud-trendy-1) S 13110 13111 4159 34819 4229 4202496 617 8462 0 0 0 0 50 2 21 0 1 0 879657394 2658304 300 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13111/statm: 649 300 253 194 0 35 0 [pid=13123] ppid=13111 vsize=10152 CPUtime=0.98 /proc/13123/stat : 13123 (clasp) R 13111 13111 4159 34819 4229 4202496 2704 0 0 0 96 2 0 0 23 0 1 0 879657396 10395648 2232 1283457024 134512640 136223643 4293486720 18446744073709551615 134711298 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13123/statm: 2538 2232 225 418 0 2118 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 12748 [startup+3.10865 s] /proc/loadavg: 1.07 1.02 1.00 2/42 13125 /proc/meminfo: memFree=818224/1048576 swapFree=2076380/2097144 [pid=13111] ppid=13110 vsize=2596 CPUtime=0.52 /proc/13111/stat : 13111 (aspcud-trendy-1) S 13110 13111 4159 34819 4229 4202496 617 8462 0 0 0 0 50 2 21 0 1 0 879657394 2658304 300 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13111/statm: 649 300 253 194 0 35 0 [pid=13123] ppid=13111 vsize=10152 CPUtime=2.58 /proc/13123/stat : 13123 (clasp) R 13111 13111 4159 34819 4229 4202496 2709 0 0 0 256 2 0 0 25 0 1 0 879657396 10395648 2237 1283457024 134512640 136223643 4293486720 18446744073709551615 134704872 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13123/statm: 2538 2237 225 418 0 2118 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 12748 [startup+6.30953 s] /proc/loadavg: 1.07 1.02 1.00 2/42 13125 /proc/meminfo: memFree=817604/1048576 swapFree=2076380/2097144 [pid=13111] ppid=13110 vsize=2596 CPUtime=0.52 /proc/13111/stat : 13111 (aspcud-trendy-1) S 13110 13111 4159 34819 4229 4202496 617 8462 0 0 0 0 50 2 21 0 1 0 879657394 2658304 300 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13111/statm: 649 300 253 194 0 35 0 [pid=13123] ppid=13111 vsize=11208 CPUtime=5.77 /proc/13123/stat : 13123 (clasp) R 13111 13111 4159 34819 4229 4202496 2982 0 0 0 575 2 0 0 25 0 1 0 879657396 11476992 2510 1283457024 134512640 136223643 4293486720 18446744073709551615 134630780 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13123/statm: 2802 2510 225 418 0 2382 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 13804 [startup+12.7123 s] /proc/loadavg: 1.06 1.02 1.00 2/42 13125 /proc/meminfo: memFree=817240/1048576 swapFree=2076380/2097144 [pid=13111] ppid=13110 vsize=2596 CPUtime=0.52 /proc/13111/stat : 13111 (aspcud-trendy-1) S 13110 13111 4159 34819 4229 4202496 617 8462 0 0 0 0 50 2 21 0 1 0 879657394 2658304 300 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13111/statm: 649 300 253 194 0 35 0 [pid=13123] ppid=13111 vsize=11472 CPUtime=12.16 /proc/13123/stat : 13123 (clasp) R 13111 13111 4159 34819 4229 4202496 3060 0 0 0 1214 2 0 0 25 0 1 0 879657396 11747328 2588 1283457024 134512640 136223643 4293486720 18446744073709551615 134664693 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13123/statm: 2868 2588 225 418 0 2448 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 14068 [startup+25.505 s] /proc/loadavg: 1.05 1.01 1.00 2/42 13125 /proc/meminfo: memFree=816868/1048576 swapFree=2076380/2097144 [pid=13111] ppid=13110 vsize=2596 CPUtime=0.52 /proc/13111/stat : 13111 (aspcud-trendy-1) S 13110 13111 4159 34819 4229 4202496 617 8462 0 0 0 0 50 2 21 0 1 0 879657394 2658304 300 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13111/statm: 649 300 253 194 0 35 0 [pid=13123] ppid=13111 vsize=11760 CPUtime=24.94 /proc/13123/stat : 13123 (clasp) R 13111 13111 4159 34819 4229 4202496 3121 0 0 0 2492 2 0 0 25 0 1 0 879657396 12042240 2649 1283457024 134512640 136223643 4293486720 18446744073709551615 134711285 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13123/statm: 2940 2649 225 418 0 2520 0 Current children cumulated CPU time (s) 25.46 Current children cumulated vsize (KiB) 14356 [startup+51.1094 s] /proc/loadavg: 1.03 1.01 1.00 2/42 13125 /proc/meminfo: memFree=816620/1048576 swapFree=2076380/2097144 [pid=13111] ppid=13110 vsize=2596 CPUtime=0.52 /proc/13111/stat : 13111 (aspcud-trendy-1) S 13110 13111 4159 34819 4229 4202496 617 8462 0 0 0 0 50 2 21 0 1 0 879657394 2658304 300 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13111/statm: 649 300 253 194 0 35 0 [pid=13123] ppid=13111 vsize=12024 CPUtime=50.46 /proc/13123/stat : 13123 (clasp) R 13111 13111 4159 34819 4229 4202496 3193 0 0 0 5044 2 0 0 25 0 1 0 879657396 12312576 2721 1283457024 134512640 136223643 4293486720 18446744073709551615 134712559 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13123/statm: 3006 2721 225 418 0 2586 0 Current children cumulated CPU time (s) 50.98 Current children cumulated vsize (KiB) 14620 [startup+102.311 s] /proc/loadavg: 1.01 1.01 1.00 2/42 13125 /proc/meminfo: memFree=815876/1048576 swapFree=2076380/2097144 [pid=13111] ppid=13110 vsize=2596 CPUtime=0.52 /proc/13111/stat : 13111 (aspcud-trendy-1) S 13110 13111 4159 34819 4229 4202496 617 8462 0 0 0 0 50 2 21 0 1 0 879657394 2658304 300 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13111/statm: 649 300 253 194 0 35 0 [pid=13123] ppid=13111 vsize=12552 CPUtime=101.6 /proc/13123/stat : 13123 (clasp) R 13111 13111 4159 34819 4229 4202496 3335 0 0 0 10158 2 0 0 25 0 1 0 879657396 12853248 2863 1283457024 134512640 136223643 4293486720 18446744073709551615 134611128 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13123/statm: 3138 2863 225 418 0 2718 0 Current children cumulated CPU time (s) 102.12 Current children cumulated vsize (KiB) 15148 [startup+162.305 s] /proc/loadavg: 1.00 1.00 1.00 2/42 13125 /proc/meminfo: memFree=815628/1048576 swapFree=2076380/2097144 [pid=13111] ppid=13110 vsize=2596 CPUtime=0.52 /proc/13111/stat : 13111 (aspcud-trendy-1) S 13110 13111 4159 34819 4229 4202496 617 8462 0 0 0 0 50 2 21 0 1 0 879657394 2658304 300 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13111/statm: 649 300 253 194 0 35 0 [pid=13123] ppid=13111 vsize=12948 CPUtime=161.53 /proc/13123/stat : 13123 (clasp) R 13111 13111 4159 34819 4229 4202496 3411 0 0 0 16151 2 0 0 25 0 1 0 879657396 13258752 2939 1283457024 134512640 136223643 4293486720 18446744073709551615 134711272 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13123/statm: 3237 2939 225 418 0 2817 0 Current children cumulated CPU time (s) 162.05 Current children cumulated vsize (KiB) 15544 [startup+222.311 s] /proc/loadavg: 1.00 1.00 1.00 2/42 13125 /proc/meminfo: memFree=815504/1048576 swapFree=2076380/2097144 [pid=13111] ppid=13110 vsize=2596 CPUtime=0.52 /proc/13111/stat : 13111 (aspcud-trendy-1) S 13110 13111 4159 34819 4229 4202496 617 8462 0 0 0 0 50 2 21 0 1 0 879657394 2658304 300 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13111/statm: 649 300 253 194 0 35 0 [pid=13123] ppid=13111 vsize=12948 CPUtime=221.47 /proc/13123/stat : 13123 (clasp) R 13111 13111 4159 34819 4229 4202496 3423 0 0 0 22145 2 0 0 25 0 1 0 879657396 13258752 2951 1283457024 134512640 136223643 4293486720 18446744073709551615 134929167 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13123/statm: 3237 2951 225 418 0 2817 0 Current children cumulated CPU time (s) 221.99 Current children cumulated vsize (KiB) 15544 [startup+282.307 s] /proc/loadavg: 1.00 1.00 1.00 2/42 13125 /proc/meminfo: memFree=815256/1048576 swapFree=2076380/2097144 [pid=13111] ppid=13110 vsize=2596 CPUtime=0.52 /proc/13111/stat : 13111 (aspcud-trendy-1) S 13110 13111 4159 34819 4229 4202496 617 8462 0 0 0 0 50 2 21 0 1 0 879657394 2658304 300 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13111/statm: 649 300 253 194 0 35 0 [pid=13123] ppid=13111 vsize=13212 CPUtime=281.42 /proc/13123/stat : 13123 (clasp) R 13111 13111 4159 34819 4229 4202496 3489 0 0 0 28138 4 0 0 25 0 1 0 879657396 13529088 3017 1283457024 134512640 136223643 4293486720 18446744073709551615 134711747 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13123/statm: 3303 3017 225 418 0 2883 0 Current children cumulated CPU time (s) 281.94 Current children cumulated vsize (KiB) 15808 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.408 s] /proc/loadavg: 1.00 1.00 1.00 2/42 13125 /proc/meminfo: memFree=815256/1048576 swapFree=2076380/2097144 [pid=13111] ppid=13110 vsize=2596 CPUtime=0.52 /proc/13111/stat : 13111 (aspcud-trendy-1) S 13110 13111 4159 34819 4229 4202496 617 8462 0 0 0 0 50 2 21 0 1 0 879657394 2658304 300 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13111/statm: 649 300 253 194 0 35 0 [pid=13123] ppid=13111 vsize=13212 CPUtime=289.52 /proc/13123/stat : 13123 (clasp) R 13111 13111 4159 34819 4229 4202496 3489 0 0 0 28948 4 0 0 25 0 1 0 879657396 13529088 3017 1283457024 134512640 136223643 4293486720 18446744073709551615 134611128 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13123/statm: 3303 3017 225 418 0 2883 0 Current children cumulated CPU time (s) 290.04 Current children cumulated vsize (KiB) 15808 Sending User defined signal 1 to process tree (bottom up) Sleeping 10 seconds Solver just ended. Dumping a history of the last processes samples [startup+290.408 s] /proc/loadavg: 1.00 1.00 1.00 2/42 13125 /proc/meminfo: memFree=815256/1048576 swapFree=2076380/2097144 [pid=13111] ppid=13110 vsize=2596 CPUtime=0.52 /proc/13111/stat : 13111 (aspcud-trendy-1) S 13110 13111 4159 34819 4229 4202496 617 8462 0 0 0 0 50 2 21 0 1 0 879657394 2658304 300 1283457024 134512640 135304128 4291698448 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13111/statm: 649 300 253 194 0 35 0 [pid=13123] ppid=13111 vsize=13212 CPUtime=289.52 /proc/13123/stat : 13123 (clasp) R 13111 13111 4159 34819 4229 4202496 3489 0 0 0 28948 4 0 0 25 0 1 0 879657396 13529088 3017 1283457024 134512640 136223643 4293486720 18446744073709551615 134611128 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13123/statm: 3303 3017 225 418 0 2883 0 Current children cumulated CPU time (s) 290.04 Current children cumulated vsize (KiB) 15808 Child status: 0 Real time (s): 290.426 CPU time (s): 290.058 CPU user time (s): 289.982 CPU system time (s): 0.076004 CPU usage (%): 99.8733 Max. virtual memory (cumulated for all children) (KiB): 15808 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.982 system time used= 0.076004 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 15173 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= 542 involuntary context switches= 3968 runsolver used 0 second user time and 0 second system time The end