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/201108291842/aspcud-1.5/rand390.cudf.dudf-random.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-random//rand390.cudf /home/misc2010/tmp/201108291842/aspcud-1.5/rand390.cudf.dudf-random.result -notuptodate,-removed,-changed 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.26 1.15 0.99 3/34 19350 /proc/meminfo: memFree=649240/1048576 swapFree=0/0 [pid=19349] ppid=19348 vsize=2588 CPUtime=0 /proc/19349/stat : 19349 (aspcud-1.5) R 19348 19349 17511 34816 17511 4202496 366 0 0 0 0 0 0 0 25 0 1 0 46061801 2650112 280 1283457024 134512640 135304128 4288947280 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/19349/statm: 647 280 234 194 0 34 0 [pid=19350] ppid=19349 vsize=2588 CPUtime=0 /proc/19350/stat : 19350 (aspcud-1.5) R 19349 19349 17511 34816 17511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 46061801 2650112 46 1283457024 134512640 135304128 4288947280 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/19350/statm: 647 46 0 194 0 34 0 [startup+0.123506 s] /proc/loadavg: 1.26 1.15 0.99 3/34 19350 /proc/meminfo: memFree=649240/1048576 swapFree=0/0 [pid=19349] ppid=19348 vsize=2596 CPUtime=0 /proc/19349/stat : 19349 (aspcud-1.5) S 19348 19349 17511 34816 17511 4202496 584 1516 0 0 0 0 0 0 25 0 1 0 46061801 2658304 299 1283457024 134512640 135304128 4288947280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19349/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.206598 s] /proc/loadavg: 1.26 1.15 0.99 3/34 19350 /proc/meminfo: memFree=649240/1048576 swapFree=0/0 [pid=19349] ppid=19348 vsize=2596 CPUtime=0 /proc/19349/stat : 19349 (aspcud-1.5) S 19348 19349 17511 34816 17511 4202496 584 1516 0 0 0 0 0 0 25 0 1 0 46061801 2658304 299 1283457024 134512640 135304128 4288947280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19349/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.306604 s] /proc/loadavg: 1.26 1.15 0.99 3/34 19350 /proc/meminfo: memFree=649240/1048576 swapFree=0/0 [pid=19349] ppid=19348 vsize=2596 CPUtime=0 /proc/19349/stat : 19349 (aspcud-1.5) S 19348 19349 17511 34816 17511 4202496 584 1516 0 0 0 0 0 0 25 0 1 0 46061801 2658304 299 1283457024 134512640 135304128 4288947280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19349/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.70872 s] /proc/loadavg: 1.26 1.15 0.99 3/34 19350 /proc/meminfo: memFree=649240/1048576 swapFree=0/0 [pid=19349] ppid=19348 vsize=2596 CPUtime=0 /proc/19349/stat : 19349 (aspcud-1.5) S 19348 19349 17511 34816 17511 4202496 584 1516 0 0 0 0 0 0 25 0 1 0 46061801 2658304 299 1283457024 134512640 135304128 4288947280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19349/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50669 s] /proc/loadavg: 1.24 1.14 0.99 2/37 19360 /proc/meminfo: memFree=617104/1048576 swapFree=0/0 [pid=19349] ppid=19348 vsize=2596 CPUtime=0 /proc/19349/stat : 19349 (aspcud-1.5) S 19348 19349 17511 34816 17511 4202496 584 1516 0 0 0 0 0 0 25 0 1 0 46061801 2658304 299 1283457024 134512640 135304128 4288947280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19349/statm: 649 299 251 194 0 36 0 [pid=19358] ppid=19349 vsize=1924 CPUtime=0 /proc/19358/stat : 19358 (clasp) S 19349 19349 17511 34816 17511 4202496 292 0 0 0 0 0 0 0 25 0 1 0 46061802 1970176 159 1283457024 134512640 136285277 4287560432 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/19358/statm: 481 159 144 433 0 46 0 [pid=19359] ppid=19349 vsize=2584 CPUtime=0 /proc/19359/stat : 19359 (gringo) S 19349 19349 17511 34816 17511 4202496 405 0 0 0 0 0 0 0 25 0 1 0 46061802 2646016 272 1283457024 134512640 136933539 4288416816 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/19359/statm: 646 272 242 592 0 51 0 [pid=19360] ppid=19349 vsize=25004 CPUtime=1.28 /proc/19360/stat : 19360 (cudf2lp) R 19349 19349 17511 34816 17511 4202496 7167 0 0 0 126 2 0 0 25 0 1 0 46061802 25604096 5568 1283457024 134512640 135786343 4290797184 18446744073709551615 134584758 0 0 6 0 0 0 0 17 0 0 0 0 /proc/19360/statm: 6251 5568 128 311 0 5938 0 Current children cumulated CPU time (s) 1.28 Current children cumulated vsize (KiB) 32108 [startup+3.11167 s] /proc/loadavg: 1.24 1.14 0.99 2/37 19360 /proc/meminfo: memFree=576896/1048576 swapFree=0/0 [pid=19349] ppid=19348 vsize=2596 CPUtime=2.24 /proc/19349/stat : 19349 (aspcud-1.5) S 19348 19349 17511 34816 17511 4202496 585 14423 0 0 0 0 217 7 18 0 1 0 46061801 2658304 299 1283457024 134512640 135304128 4288947280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19349/statm: 649 299 251 194 0 36 0 [pid=19358] ppid=19349 vsize=14688 CPUtime=0.09 /proc/19358/stat : 19358 (clasp) R 19349 19349 17511 34816 17511 4202496 3782 0 0 0 5 4 0 0 18 0 1 0 46061802 15040512 3263 1283457024 134512640 136285277 4287560432 18446744073709551615 135658630 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19358/statm: 3672 3263 177 433 0 3237 0 [pid=19359] ppid=19349 vsize=22060 CPUtime=0.48 /proc/19359/stat : 19359 (gringo) R 19349 19349 17511 34816 17511 4202496 6317 0 0 0 45 3 0 0 18 0 1 0 46061802 22589440 4365 1283457024 134512640 136933539 4288416816 18446744073709551615 135633710 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19359/statm: 5515 4365 253 592 0 4920 0 Current children cumulated CPU time (s) 2.81 Current children cumulated vsize (KiB) 39344 [startup+6.31248 s] /proc/loadavg: 1.24 1.14 0.99 2/35 19360 /proc/meminfo: memFree=589328/1048576 swapFree=0/0 [pid=19349] ppid=19348 vsize=2596 CPUtime=3.25 /proc/19349/stat : 19349 (aspcud-1.5) S 19348 19349 17511 34816 17511 4202496 585 25626 0 0 0 0 313 12 15 0 1 0 46061801 2658304 299 1283457024 134512640 135304128 4288947280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19349/statm: 649 299 251 194 0 36 0 [pid=19358] ppid=19349 vsize=34376 CPUtime=2.76 /proc/19358/stat : 19358 (clasp) R 19349 19349 17511 34816 17511 4202496 10227 0 0 0 272 4 0 0 22 0 1 0 46061802 35201024 8365 1283457024 134512640 136285277 4287560432 18446744073709551615 134734287 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19358/statm: 8594 8365 234 433 0 8159 0 Current children cumulated CPU time (s) 6.01 Current children cumulated vsize (KiB) 36972 [startup+12.7138 s] /proc/loadavg: 1.20 1.14 0.99 2/35 19360 /proc/meminfo: memFree=488524/1048576 swapFree=0/0 [pid=19349] ppid=19348 vsize=2596 CPUtime=3.25 /proc/19349/stat : 19349 (aspcud-1.5) S 19348 19349 17511 34816 17511 4202496 585 25626 0 0 0 0 313 12 15 0 1 0 46061801 2658304 299 1283457024 134512640 135304128 4288947280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19349/statm: 649 299 251 194 0 36 0 [pid=19358] ppid=19349 vsize=134704 CPUtime=9.16 /proc/19358/stat : 19358 (clasp) R 19349 19349 17511 34816 17511 4202496 35289 0 0 0 898 18 0 0 25 0 1 0 46061802 137936896 33427 1283457024 134512640 136285277 4287560432 18446744073709551615 134686319 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19358/statm: 33676 33427 234 433 0 33241 0 Current children cumulated CPU time (s) 12.41 Current children cumulated vsize (KiB) 137300 [startup+25.5068 s] /proc/loadavg: 1.17 1.13 0.99 2/35 19360 /proc/meminfo: memFree=474884/1048576 swapFree=0/0 [pid=19349] ppid=19348 vsize=2596 CPUtime=3.25 /proc/19349/stat : 19349 (aspcud-1.5) S 19348 19349 17511 34816 17511 4202496 585 25626 0 0 0 0 313 12 15 0 1 0 46061801 2658304 299 1283457024 134512640 135304128 4288947280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19349/statm: 649 299 251 194 0 36 0 [pid=19358] ppid=19349 vsize=148332 CPUtime=21.94 /proc/19358/stat : 19358 (clasp) R 19349 19349 17511 34816 17511 4202496 38700 0 0 0 2174 20 0 0 25 0 1 0 46061802 151891968 36838 1283457024 134512640 136285277 4287560432 18446744073709551615 134955205 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19358/statm: 37083 36838 234 433 0 36648 0 Current children cumulated CPU time (s) 25.19 Current children cumulated vsize (KiB) 150928 [startup+51.1026 s] /proc/loadavg: 1.11 1.12 0.99 2/37 19364 /proc/meminfo: memFree=297912/1048576 swapFree=0/0 [pid=19349] ppid=19348 vsize=2596 CPUtime=3.25 /proc/19349/stat : 19349 (aspcud-1.5) S 19348 19349 17511 34816 17511 4202496 585 25626 0 0 0 0 313 12 15 0 1 0 46061801 2658304 299 1283457024 134512640 135304128 4288947280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19349/statm: 649 299 251 194 0 36 0 [pid=19358] ppid=19349 vsize=324896 CPUtime=47.53 /proc/19358/stat : 19358 (clasp) R 19349 19349 17511 34816 17511 4202496 82816 0 0 0 4721 32 0 0 25 0 1 0 46061802 332693504 80954 1283457024 134512640 136285277 4287560432 18446744073709551615 134650368 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19358/statm: 81224 80954 234 433 0 80789 0 Current children cumulated CPU time (s) 50.78 Current children cumulated vsize (KiB) 327492 [startup+102.307 s] /proc/loadavg: 1.04 1.10 0.99 2/37 19369 /proc/meminfo: memFree=194992/1048576 swapFree=0/0 [pid=19349] ppid=19348 vsize=2596 CPUtime=3.25 /proc/19349/stat : 19349 (aspcud-1.5) S 19348 19349 17511 34816 17511 4202496 585 25626 0 0 0 0 313 12 15 0 1 0 46061801 2658304 299 1283457024 134512640 135304128 4288947280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19349/statm: 649 299 251 194 0 36 0 [pid=19358] ppid=19349 vsize=427412 CPUtime=98.69 /proc/19358/stat : 19358 (clasp) R 19349 19349 17511 34816 17511 4202496 108455 0 0 0 9830 39 0 0 25 0 1 0 46061802 437669888 106593 1283457024 134512640 136285277 4287560432 18446744073709551615 134650371 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19358/statm: 106853 106593 234 433 0 106418 0 Current children cumulated CPU time (s) 101.94 Current children cumulated vsize (KiB) 430008 [startup+162.312 s] /proc/loadavg: 1.01 1.08 0.99 2/36 19371 /proc/meminfo: memFree=6404/1048576 swapFree=0/0 [pid=19349] ppid=19348 vsize=2596 CPUtime=3.25 /proc/19349/stat : 19349 (aspcud-1.5) S 19348 19349 17511 34816 17511 4202496 585 25626 0 0 0 0 313 12 15 0 1 0 46061801 2658304 299 1283457024 134512640 135304128 4288947280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19349/statm: 649 299 251 194 0 36 0 [pid=19358] ppid=19349 vsize=618392 CPUtime=158.63 /proc/19358/stat : 19358 (clasp) R 19349 19349 17511 34816 17511 4202496 156178 0 0 0 15811 52 0 0 25 0 1 0 46061802 633233408 154316 1283457024 134512640 136285277 4287560432 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19358/statm: 154598 154316 234 433 0 154163 0 Current children cumulated CPU time (s) 161.88 Current children cumulated vsize (KiB) 620988 [startup+222.308 s] /proc/loadavg: 1.00 1.06 0.99 2/35 19371 /proc/meminfo: memFree=5584/1048576 swapFree=0/0 [pid=19349] ppid=19348 vsize=2596 CPUtime=3.25 /proc/19349/stat : 19349 (aspcud-1.5) S 19348 19349 17511 34816 17511 4202496 585 25626 0 0 0 0 313 12 15 0 1 0 46061801 2658304 299 1283457024 134512640 135304128 4288947280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19349/statm: 649 299 251 194 0 36 0 [pid=19358] ppid=19349 vsize=680632 CPUtime=218.57 /proc/19358/stat : 19358 (clasp) R 19349 19349 17511 34816 17511 4202496 171724 0 0 0 21791 66 0 0 25 0 1 0 46061802 696967168 169862 1283457024 134512640 136285277 4287560432 18446744073709551615 134959967 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19358/statm: 170158 169862 234 433 0 169723 0 Current children cumulated CPU time (s) 221.82 Current children cumulated vsize (KiB) 683228 [startup+282.312 s] /proc/loadavg: 1.00 1.05 0.99 2/35 19371 /proc/meminfo: memFree=5480/1048576 swapFree=0/0 [pid=19349] ppid=19348 vsize=2596 CPUtime=3.25 /proc/19349/stat : 19349 (aspcud-1.5) S 19348 19349 17511 34816 17511 4202496 585 25626 0 0 0 0 313 12 15 0 1 0 46061801 2658304 299 1283457024 134512640 135304128 4288947280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19349/statm: 649 299 251 194 0 36 0 [pid=19358] ppid=19349 vsize=743316 CPUtime=278.52 /proc/19358/stat : 19358 (clasp) R 19349 19349 17511 34816 17511 4202496 187386 0 0 0 27782 70 0 0 25 0 1 0 46061802 761155584 185524 1283457024 134512640 136285277 4287560432 18446744073709551615 134649451 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19358/statm: 185829 185524 234 433 0 185394 0 Current children cumulated CPU time (s) 281.77 Current children cumulated vsize (KiB) 745912 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.615 s] /proc/loadavg: 1.00 1.05 0.99 2/35 19371 /proc/meminfo: memFree=5480/1048576 swapFree=0/0 [pid=19349] ppid=19348 vsize=2596 CPUtime=3.25 /proc/19349/stat : 19349 (aspcud-1.5) S 19348 19349 17511 34816 17511 4202496 585 25626 0 0 0 0 313 12 15 0 1 0 46061801 2658304 299 1283457024 134512640 135304128 4288947280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19349/statm: 649 299 251 194 0 36 0 [pid=19358] ppid=19349 vsize=743316 CPUtime=286.82 /proc/19358/stat : 19358 (clasp) R 19349 19349 17511 34816 17511 4202496 187387 0 0 0 28612 70 0 0 25 0 1 0 46061802 761155584 185525 1283457024 134512640 136285277 4287560432 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/19358/statm: 185829 185525 234 433 0 185394 0 Current children cumulated CPU time (s) 290.07 Current children cumulated vsize (KiB) 745912 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.729 s] /proc/loadavg: 1.00 1.05 0.99 2/35 19371 /proc/meminfo: memFree=5480/1048576 swapFree=0/0 [pid=19349] ppid=19348 vsize=2596 CPUtime=290.14 /proc/19349/stat : 19349 (aspcud-1.5) S 19348 19349 17511 34816 17511 4202496 610 213021 0 0 0 0 28926 88 15 0 1 0 46061801 2658304 306 1283457024 134512640 135304128 4288947280 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0 /proc/19349/statm: 649 306 258 194 0 36 0 Current children cumulated CPU time (s) 290.14 Current children cumulated vsize (KiB) 2596 [startup+290.805 s] /proc/loadavg: 1.00 1.05 0.99 2/35 19371 /proc/meminfo: memFree=5480/1048576 swapFree=0/0 [pid=19349] ppid=19348 vsize=2596 CPUtime=290.14 /proc/19349/stat : 19349 (aspcud-1.5) D 19348 19349 17511 34816 17511 4202496 614 213226 0 4 0 0 28926 88 17 0 1 0 46061801 2658304 306 1283457024 134512640 135304128 4288947280 18446744073709551615 4294960130 0 0 16902 1132543225 18446744071564332000 0 0 17 0 0 0 0 /proc/19349/statm: 649 306 258 194 0 36 0 Current children cumulated CPU time (s) 290.14 Current children cumulated vsize (KiB) 2596 Child status: 0 Real time (s): 290.885 CPU time (s): 290.154 CPU user time (s): 289.266 CPU system time (s): 0.888055 CPU usage (%): 99.7487 Max. virtual memory (cumulated for all children) (KiB): 745912 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.266 system time used= 0.888055 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 217543 page faults= 9 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 1371 involuntary context switches= 4623 runsolver used 0 second user time and 0.012 second system time The end