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/rand2d2fd0.cudf.difficult.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/2010/difficult//rand2d2fd0.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand2d2fd0.cudf.difficult.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.09 1.04 1.01 5/42 13851 /proc/meminfo: memFree=625628/1048576 swapFree=2076380/2097144 [pid=13849] ppid=13848 vsize=2588 CPUtime=0 /proc/13849/stat : 13849 (aspcud-trendy-1) S 13848 13849 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 18 0 1 0 879838739 2650112 282 1283457024 134512640 135304128 4288484352 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/13849/statm: 647 282 237 194 0 33 0 [pid=13850] ppid=13849 vsize=2588 CPUtime=0.01 /proc/13850/stat : 13850 (aspcud-trendy-1) R 13849 13849 4159 34819 4229 4202560 105 0 0 0 0 1 0 0 25 0 1 0 879838740 2650112 128 1283457024 134512640 135304128 4288484352 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/13850/statm: 647 128 82 194 0 33 0 [pid=13851] ppid=13850 vsize=2588 CPUtime=0 /proc/13851/stat : 13851 (aspcud-trendy-1) R 13850 13849 4159 34819 4229 4202560 0 0 0 0 0 0 0 0 25 0 1 0 879838740 2650112 46 1283457024 134512640 135304128 4288484352 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/13851/statm: 647 46 0 194 0 33 0 [startup+0.152015 s] /proc/loadavg: 1.09 1.04 1.01 5/42 13851 /proc/meminfo: memFree=625628/1048576 swapFree=2076380/2097144 [pid=13849] ppid=13848 vsize=2600 CPUtime=0.01 /proc/13849/stat : 13849 (aspcud-trendy-1) S 13848 13849 4159 34819 4229 4202496 624 2217 0 0 0 0 0 1 25 0 1 0 879838739 2662400 301 1283457024 134512640 135304128 4288484352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13849/statm: 650 301 253 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+0.202034 s] /proc/loadavg: 1.09 1.04 1.01 5/42 13851 /proc/meminfo: memFree=625628/1048576 swapFree=2076380/2097144 [pid=13849] ppid=13848 vsize=2600 CPUtime=0.01 /proc/13849/stat : 13849 (aspcud-trendy-1) S 13848 13849 4159 34819 4229 4202496 624 2217 0 0 0 0 0 1 25 0 1 0 879838739 2662400 301 1283457024 134512640 135304128 4288484352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13849/statm: 650 301 253 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+0.312035 s] /proc/loadavg: 1.09 1.04 1.01 5/42 13851 /proc/meminfo: memFree=625628/1048576 swapFree=2076380/2097144 [pid=13849] ppid=13848 vsize=2600 CPUtime=0.01 /proc/13849/stat : 13849 (aspcud-trendy-1) S 13848 13849 4159 34819 4229 4202496 624 2217 0 0 0 0 0 1 25 0 1 0 879838739 2662400 301 1283457024 134512640 135304128 4288484352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13849/statm: 650 301 253 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+0.712128 s] /proc/loadavg: 1.09 1.04 1.01 5/42 13851 /proc/meminfo: memFree=625628/1048576 swapFree=2076380/2097144 [pid=13849] ppid=13848 vsize=2600 CPUtime=0.01 /proc/13849/stat : 13849 (aspcud-trendy-1) S 13848 13849 4159 34819 4229 4202496 624 2217 0 0 0 0 0 1 25 0 1 0 879838739 2662400 301 1283457024 134512640 135304128 4288484352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13849/statm: 650 301 253 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+1.51231 s] /proc/loadavg: 1.09 1.04 1.01 2/44 13863 /proc/meminfo: memFree=586316/1048576 swapFree=2076380/2097144 [pid=13849] ppid=13848 vsize=2600 CPUtime=0.96 /proc/13849/stat : 13849 (aspcud-trendy-1) S 13848 13849 4159 34819 4229 4202496 624 11436 0 0 0 0 92 4 18 0 1 0 879838739 2662400 301 1283457024 134512640 135304128 4288484352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13849/statm: 650 301 253 194 0 36 0 [pid=13861] ppid=13849 vsize=13836 CPUtime=0.09 /proc/13861/stat : 13861 (clasp) R 13849 13849 4159 34819 4229 4202496 3663 0 0 0 6 3 0 0 18 0 1 0 879838741 14168064 3143 1283457024 134512640 136223643 4291186256 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13861/statm: 3459 3143 174 418 0 3039 0 [pid=13862] ppid=13849 vsize=24016 CPUtime=0.44 /proc/13862/stat : 13862 (gringo) R 13849 13849 4159 34819 4229 4202496 5926 0 0 0 41 3 0 0 18 0 1 0 879838741 24592384 4394 1283457024 134512640 136959103 4289901968 18446744073709551615 135850573 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13862/statm: 6004 4394 256 598 0 5403 0 Current children cumulated CPU time (s) 1.49 Current children cumulated vsize (KiB) 40452 [startup+3.1128 s] /proc/loadavg: 1.09 1.04 1.01 2/42 13863 /proc/meminfo: memFree=605072/1048576 swapFree=2076380/2097144 [pid=13849] ppid=13848 vsize=2600 CPUtime=1.55 /proc/13849/stat : 13849 (aspcud-trendy-1) S 13848 13849 4159 34819 4229 4202496 624 18471 0 0 0 0 147 8 15 0 1 0 879838739 2662400 301 1283457024 134512640 135304128 4288484352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13849/statm: 650 301 253 194 0 36 0 [pid=13861] ppid=13849 vsize=23148 CPUtime=1.54 /proc/13861/stat : 13861 (clasp) R 13849 13849 4159 34819 4229 4202496 6188 0 0 0 150 4 0 0 19 0 1 0 879838741 23703552 5248 1283457024 134512640 136223643 4291186256 18446744073709551615 134926787 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13861/statm: 5787 5248 225 418 0 5367 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 25748 [startup+6.31353 s] /proc/loadavg: 1.08 1.04 1.01 2/42 13863 /proc/meminfo: memFree=605072/1048576 swapFree=2076380/2097144 [pid=13849] ppid=13848 vsize=2600 CPUtime=1.55 /proc/13849/stat : 13849 (aspcud-trendy-1) S 13848 13849 4159 34819 4229 4202496 624 18471 0 0 0 0 147 8 15 0 1 0 879838739 2662400 301 1283457024 134512640 135304128 4288484352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13849/statm: 650 301 253 194 0 36 0 [pid=13861] ppid=13849 vsize=26184 CPUtime=4.74 /proc/13861/stat : 13861 (clasp) R 13849 13849 4159 34819 4229 4202496 6963 0 0 0 469 5 0 0 25 0 1 0 879838741 26812416 6023 1283457024 134512640 136223643 4291186256 18446744073709551615 134664680 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13861/statm: 6546 6023 225 418 0 6126 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 28784 [startup+12.7049 s] /proc/loadavg: 1.08 1.04 1.01 2/42 13863 /proc/meminfo: memFree=593920/1048576 swapFree=2076380/2097144 [pid=13849] ppid=13848 vsize=2600 CPUtime=1.55 /proc/13849/stat : 13849 (aspcud-trendy-1) S 13848 13849 4159 34819 4229 4202496 624 18471 0 0 0 0 147 8 15 0 1 0 879838739 2662400 301 1283457024 134512640 135304128 4288484352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13849/statm: 650 301 253 194 0 36 0 [pid=13861] ppid=13849 vsize=34560 CPUtime=11.13 /proc/13861/stat : 13861 (clasp) R 13849 13849 4159 34819 4229 4202496 9065 0 0 0 1104 9 0 0 25 0 1 0 879838741 35389440 8125 1283457024 134512640 136223643 4291186256 18446744073709551615 134712466 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13861/statm: 8640 8125 225 418 0 8220 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 37160 [startup+25.5079 s] /proc/loadavg: 1.06 1.04 1.00 2/42 13863 /proc/meminfo: memFree=582016/1048576 swapFree=2076380/2097144 [pid=13849] ppid=13848 vsize=2600 CPUtime=1.55 /proc/13849/stat : 13849 (aspcud-trendy-1) S 13848 13849 4159 34819 4229 4202496 624 18471 0 0 0 0 147 8 15 0 1 0 879838739 2662400 301 1283457024 134512640 135304128 4288484352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13849/statm: 650 301 253 194 0 36 0 [pid=13861] ppid=13849 vsize=46528 CPUtime=23.9 /proc/13861/stat : 13861 (clasp) R 13849 13849 4159 34819 4229 4202496 12040 0 0 0 2380 10 0 0 25 0 1 0 879838741 47644672 11100 1283457024 134512640 136223643 4291186256 18446744073709551615 134664705 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13861/statm: 11632 11100 225 418 0 11212 0 Current children cumulated CPU time (s) 25.45 Current children cumulated vsize (KiB) 49128 [startup+51.1139 s] /proc/loadavg: 1.04 1.03 1.00 2/42 13863 /proc/meminfo: memFree=567260/1048576 swapFree=2076380/2097144 [pid=13849] ppid=13848 vsize=2600 CPUtime=1.55 /proc/13849/stat : 13849 (aspcud-trendy-1) S 13848 13849 4159 34819 4229 4202496 624 18471 0 0 0 0 147 8 15 0 1 0 879838739 2662400 301 1283457024 134512640 135304128 4288484352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13849/statm: 650 301 253 194 0 36 0 [pid=13861] ppid=13849 vsize=63200 CPUtime=49.49 /proc/13861/stat : 13861 (clasp) R 13849 13849 4159 34819 4229 4202496 16223 0 0 0 4939 10 0 0 25 0 1 0 879838741 64716800 15283 1283457024 134512640 136223643 4291186256 18446744073709551615 134704872 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13861/statm: 15800 15283 225 418 0 15380 0 Current children cumulated CPU time (s) 51.04 Current children cumulated vsize (KiB) 65800 [startup+102.307 s] /proc/loadavg: 1.01 1.02 1.00 2/42 13863 /proc/meminfo: memFree=506500/1048576 swapFree=2076380/2097144 [pid=13849] ppid=13848 vsize=2600 CPUtime=1.55 /proc/13849/stat : 13849 (aspcud-trendy-1) S 13848 13849 4159 34819 4229 4202496 624 18471 0 0 0 0 147 8 15 0 1 0 879838739 2662400 301 1283457024 134512640 135304128 4288484352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13849/statm: 650 301 253 194 0 36 0 [pid=13861] ppid=13849 vsize=121836 CPUtime=100.63 /proc/13861/stat : 13861 (clasp) R 13849 13849 4159 34819 4229 4202496 30845 0 0 0 10048 15 0 0 25 0 1 0 879838741 124760064 29905 1283457024 134512640 136223643 4291186256 18446744073709551615 134711272 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13861/statm: 30459 29905 225 418 0 30039 0 Current children cumulated CPU time (s) 102.18 Current children cumulated vsize (KiB) 124436 [startup+162.312 s] /proc/loadavg: 1.00 1.02 1.00 2/42 13863 /proc/meminfo: memFree=504392/1048576 swapFree=2076380/2097144 [pid=13849] ppid=13848 vsize=2600 CPUtime=1.55 /proc/13849/stat : 13849 (aspcud-trendy-1) S 13848 13849 4159 34819 4229 4202496 624 18471 0 0 0 0 147 8 15 0 1 0 879838739 2662400 301 1283457024 134512640 135304128 4288484352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13849/statm: 650 301 253 194 0 36 0 [pid=13861] ppid=13849 vsize=123584 CPUtime=160.59 /proc/13861/stat : 13861 (clasp) R 13849 13849 4159 34819 4229 4202496 31511 0 0 0 16043 16 0 0 25 0 1 0 879838741 126550016 30361 1283457024 134512640 136223643 4291186256 18446744073709551615 134631204 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13861/statm: 30896 30361 225 418 0 30476 0 Current children cumulated CPU time (s) 162.14 Current children cumulated vsize (KiB) 126184 [startup+222.307 s] /proc/loadavg: 1.00 1.01 1.00 2/42 13863 /proc/meminfo: memFree=496580/1048576 swapFree=2076380/2097144 [pid=13849] ppid=13848 vsize=2600 CPUtime=1.55 /proc/13849/stat : 13849 (aspcud-trendy-1) S 13848 13849 4159 34819 4229 4202496 624 18471 0 0 0 0 147 8 15 0 1 0 879838739 2662400 301 1283457024 134512640 135304128 4288484352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13849/statm: 650 301 253 194 0 36 0 [pid=13861] ppid=13849 vsize=131052 CPUtime=220.57 /proc/13861/stat : 13861 (clasp) R 13849 13849 4159 34819 4229 4202496 33873 0 0 0 22038 19 0 0 25 0 1 0 879838741 134197248 32227 1283457024 134512640 136223643 4291186256 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13861/statm: 32763 32227 225 418 0 32343 0 Current children cumulated CPU time (s) 222.12 Current children cumulated vsize (KiB) 133652 [startup+282.312 s] /proc/loadavg: 1.00 1.01 1.00 2/42 13863 /proc/meminfo: memFree=496580/1048576 swapFree=2076380/2097144 [pid=13849] ppid=13848 vsize=2600 CPUtime=1.55 /proc/13849/stat : 13849 (aspcud-trendy-1) S 13848 13849 4159 34819 4229 4202496 624 18471 0 0 0 0 147 8 15 0 1 0 879838739 2662400 301 1283457024 134512640 135304128 4288484352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13849/statm: 650 301 253 194 0 36 0 [pid=13861] ppid=13849 vsize=131052 CPUtime=280.51 /proc/13861/stat : 13861 (clasp) R 13849 13849 4159 34819 4229 4202496 33874 0 0 0 28032 19 0 0 25 0 1 0 879838741 134197248 32228 1283457024 134512640 136223643 4291186256 18446744073709551615 134631216 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13861/statm: 32763 32228 225 418 0 32343 0 Current children cumulated CPU time (s) 282.06 Current children cumulated vsize (KiB) 133652 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.304 s] /proc/loadavg: 1.00 1.01 1.00 2/42 13863 /proc/meminfo: memFree=496580/1048576 swapFree=2076380/2097144 [pid=13849] ppid=13848 vsize=2600 CPUtime=1.55 /proc/13849/stat : 13849 (aspcud-trendy-1) S 13848 13849 4159 34819 4229 4202496 624 18471 0 0 0 0 147 8 15 0 1 0 879838739 2662400 301 1283457024 134512640 135304128 4288484352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13849/statm: 650 301 253 194 0 36 0 [pid=13861] ppid=13849 vsize=131052 CPUtime=288.49 /proc/13861/stat : 13861 (clasp) R 13849 13849 4159 34819 4229 4202496 33874 0 0 0 28830 19 0 0 25 0 1 0 879838741 134197248 32228 1283457024 134512640 136223643 4291186256 18446744073709551615 134704907 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13861/statm: 32763 32228 225 418 0 32343 0 Current children cumulated CPU time (s) 290.04 Current children cumulated vsize (KiB) 133652 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.304 s] /proc/loadavg: 1.00 1.01 1.00 2/42 13863 /proc/meminfo: memFree=496580/1048576 swapFree=2076380/2097144 [pid=13849] ppid=13848 vsize=2600 CPUtime=1.55 /proc/13849/stat : 13849 (aspcud-trendy-1) S 13848 13849 4159 34819 4229 4202496 624 18471 0 0 0 0 147 8 15 0 1 0 879838739 2662400 301 1283457024 134512640 135304128 4288484352 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/13849/statm: 650 301 253 194 0 36 0 [pid=13861] ppid=13849 vsize=131052 CPUtime=288.49 /proc/13861/stat : 13861 (clasp) R 13849 13849 4159 34819 4229 4202496 33874 0 0 0 28830 19 0 0 25 0 1 0 879838741 134197248 32228 1283457024 134512640 136223643 4291186256 18446744073709551615 134704907 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/13861/statm: 32763 32228 225 418 0 32343 0 Current children cumulated CPU time (s) 290.04 Current children cumulated vsize (KiB) 133652 Child status: 0 Real time (s): 290.331 CPU time (s): 290.082 CPU user time (s): 289.786 CPU system time (s): 0.296018 CPU usage (%): 99.9144 Max. virtual memory (cumulated for all children) (KiB): 134924 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.786 system time used= 0.296018 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 55576 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= 714 involuntary context switches= 3927 runsolver used 0 second user time and 0 second system time The end