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/rand461.cudf.dudf-random.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-random//rand461.cudf /home/misc2010/tmp/201108291842/aspcud-1.5/rand461.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.62 1.31 1.13 4/34 21613
/proc/meminfo: memFree=372344/1048576 swapFree=0/0
[pid=21612] ppid=21611 vsize=2588 CPUtime=0
/proc/21612/stat : 21612 (aspcud-1.5) S 21611 21612 17511 34816 17511 4202496 375 0 0 0 0 0 0 0 18 0 1 0 46205957 2650112 280 1283457024 134512640 135304128 4291667696 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/21612/statm: 647 280 234 194 0 34 0
[pid=21613] ppid=21612 vsize=2588 CPUtime=0
/proc/21613/stat : 21613 (aspcud-1.5) R 21612 21612 17511 34816 17511 4202560 107 0 0 0 0 0 0 0 25 0 1 0 46205957 2650112 130 1283457024 134512640 135304128 4291667696 18446744073709551615 134836576 0 0 0 65538 0 0 0 17 0 0 0 0
/proc/21613/statm: 647 130 83 194 0 34 0

[startup+0.130207 s]
/proc/loadavg: 1.62 1.31 1.13 4/34 21613
/proc/meminfo: memFree=372344/1048576 swapFree=0/0
[pid=21612] ppid=21611 vsize=2596 CPUtime=0
/proc/21612/stat : 21612 (aspcud-1.5) S 21611 21612 17511 34816 17511 4202496 585 1516 0 0 0 0 0 0 25 0 1 0 46205957 2658304 299 1283457024 134512640 135304128 4291667696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21612/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.209966 s]
/proc/loadavg: 1.62 1.31 1.13 4/34 21613
/proc/meminfo: memFree=372344/1048576 swapFree=0/0
[pid=21612] ppid=21611 vsize=2596 CPUtime=0
/proc/21612/stat : 21612 (aspcud-1.5) S 21611 21612 17511 34816 17511 4202496 585 1516 0 0 0 0 0 0 25 0 1 0 46205957 2658304 299 1283457024 134512640 135304128 4291667696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21612/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.302249 s]
/proc/loadavg: 1.62 1.31 1.13 4/34 21613
/proc/meminfo: memFree=372344/1048576 swapFree=0/0
[pid=21612] ppid=21611 vsize=2596 CPUtime=0
/proc/21612/stat : 21612 (aspcud-1.5) S 21611 21612 17511 34816 17511 4202496 585 1516 0 0 0 0 0 0 25 0 1 0 46205957 2658304 299 1283457024 134512640 135304128 4291667696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21612/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.706253 s]
/proc/loadavg: 1.62 1.31 1.13 4/34 21613
/proc/meminfo: memFree=372344/1048576 swapFree=0/0
[pid=21612] ppid=21611 vsize=2596 CPUtime=0
/proc/21612/stat : 21612 (aspcud-1.5) S 21611 21612 17511 34816 17511 4202496 585 1516 0 0 0 0 0 0 25 0 1 0 46205957 2658304 299 1283457024 134512640 135304128 4291667696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21612/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.5063 s]
/proc/loadavg: 1.62 1.31 1.13 2/37 21623
/proc/meminfo: memFree=341324/1048576 swapFree=0/0
[pid=21612] ppid=21611 vsize=2596 CPUtime=0
/proc/21612/stat : 21612 (aspcud-1.5) S 21611 21612 17511 34816 17511 4202496 585 1516 0 0 0 0 0 0 25 0 1 0 46205957 2658304 299 1283457024 134512640 135304128 4291667696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21612/statm: 649 299 251 194 0 36 0
[pid=21621] ppid=21612 vsize=1928 CPUtime=0
/proc/21621/stat : 21621 (clasp) S 21612 21612 17511 34816 17511 4202496 293 0 0 0 0 0 0 0 25 0 1 0 46205958 1974272 160 1283457024 134512640 136285277 4294668720 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/21621/statm: 482 160 144 433 0 47 0
[pid=21622] ppid=21612 vsize=2588 CPUtime=0
/proc/21622/stat : 21622 (gringo) S 21612 21612 17511 34816 17511 4202496 405 0 0 0 0 0 0 0 25 0 1 0 46205958 2650112 272 1283457024 134512640 136933539 4286790320 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/21622/statm: 647 272 242 592 0 52 0
[pid=21623] ppid=21612 vsize=25008 CPUtime=1.26
/proc/21623/stat : 21623 (cudf2lp) R 21612 21612 17511 34816 17511 4202496 7167 0 0 0 122 4 0 0 25 0 1 0 46205958 25608192 5568 1283457024 134512640 135786343 4287167248 18446744073709551615 134614712 0 0 6 0 0 0 0 17 0 0 0 0
/proc/21623/statm: 6252 5568 128 311 0 5939 0
Current children cumulated CPU time (s) 1.26
Current children cumulated vsize (KiB) 32120

[startup+3.1122 s]
/proc/loadavg: 1.62 1.31 1.13 2/37 21623
/proc/meminfo: memFree=299692/1048576 swapFree=0/0
[pid=21612] ppid=21611 vsize=2596 CPUtime=2.2
/proc/21612/stat : 21612 (aspcud-1.5) S 21611 21612 17511 34816 17511 4202496 586 14424 0 0 0 0 212 8 18 0 1 0 46205957 2658304 299 1283457024 134512640 135304128 4291667696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21612/statm: 649 299 251 194 0 36 0
[pid=21621] ppid=21612 vsize=14676 CPUtime=0.04
/proc/21621/stat : 21621 (clasp) R 21612 21612 17511 34816 17511 4202496 4029 0 0 0 4 0 0 0 18 0 1 0 46205958 15028224 3238 1283457024 134512640 136285277 4294668720 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21621/statm: 3669 3238 177 433 0 3234 0
[pid=21622] ppid=21612 vsize=22080 CPUtime=0.56
/proc/21622/stat : 21622 (gringo) R 21612 21612 17511 34816 17511 4202496 6263 0 0 0 54 2 0 0 18 0 1 0 46205958 22609920 4311 1283457024 134512640 136933539 4286790320 18446744073709551615 134813750 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/21622/statm: 5520 4311 253 592 0 4925 0
Current children cumulated CPU time (s) 2.8
Current children cumulated vsize (KiB) 39352

[startup+6.31296 s]
/proc/loadavg: 1.57 1.30 1.13 2/35 21623
/proc/meminfo: memFree=312496/1048576 swapFree=0/0
[pid=21612] ppid=21611 vsize=2596 CPUtime=3.27
/proc/21612/stat : 21612 (aspcud-1.5) S 21611 21612 17511 34816 17511 4202496 586 25555 0 0 0 0 312 15 15 0 1 0 46205957 2658304 299 1283457024 134512640 135304128 4291667696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21612/statm: 649 299 251 194 0 36 0
[pid=21621] ppid=21612 vsize=33460 CPUtime=2.73
/proc/21621/stat : 21621 (clasp) R 21612 21612 17511 34816 17511 4202496 9977 0 0 0 269 4 0 0 22 0 1 0 46205958 34263040 8124 1283457024 134512640 136285277 4294668720 18446744073709551615 134930797 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21621/statm: 8365 8124 234 433 0 7930 0
Current children cumulated CPU time (s) 6
Current children cumulated vsize (KiB) 36056

[startup+12.7044 s]
/proc/loadavg: 1.53 1.30 1.13 2/35 21623
/proc/meminfo: memFree=269476/1048576 swapFree=0/0
[pid=21612] ppid=21611 vsize=2596 CPUtime=3.27
/proc/21612/stat : 21612 (aspcud-1.5) S 21611 21612 17511 34816 17511 4202496 586 25555 0 0 0 0 312 15 15 0 1 0 46205957 2658304 299 1283457024 134512640 135304128 4291667696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21612/statm: 649 299 251 194 0 36 0
[pid=21621] ppid=21612 vsize=89916 CPUtime=9.12
/proc/21621/stat : 21621 (clasp) R 21612 21612 17511 34816 17511 4202496 24089 0 0 0 900 12 0 0 25 0 1 0 46205958 92073984 22236 1283457024 134512640 136285277 4294668720 18446744073709551615 134930675 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21621/statm: 22479 22236 234 433 0 22044 0
Current children cumulated CPU time (s) 12.39
Current children cumulated vsize (KiB) 92512

[startup+25.5074 s]
/proc/loadavg: 1.41 1.28 1.13 2/35 21623
/proc/meminfo: memFree=149196/1048576 swapFree=0/0
[pid=21612] ppid=21611 vsize=2596 CPUtime=3.27
/proc/21612/stat : 21612 (aspcud-1.5) S 21611 21612 17511 34816 17511 4202496 586 25555 0 0 0 0 312 15 15 0 1 0 46205957 2658304 299 1283457024 134512640 135304128 4291667696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21612/statm: 649 299 251 194 0 36 0
[pid=21621] ppid=21612 vsize=196880 CPUtime=21.92
/proc/21621/stat : 21621 (clasp) R 21612 21612 17511 34816 17511 4202496 50840 0 0 0 2176 16 0 0 25 0 1 0 46205958 201605120 48987 1283457024 134512640 136285277 4294668720 18446744073709551615 134930818 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21621/statm: 49220 48987 234 433 0 48785 0
Current children cumulated CPU time (s) 25.19
Current children cumulated vsize (KiB) 199476

[startup+51.1136 s]
/proc/loadavg: 1.27 1.26 1.12 2/35 21623
/proc/meminfo: memFree=84964/1048576 swapFree=0/0
[pid=21612] ppid=21611 vsize=2596 CPUtime=3.27
/proc/21612/stat : 21612 (aspcud-1.5) S 21611 21612 17511 34816 17511 4202496 586 25555 0 0 0 0 312 15 15 0 1 0 46205957 2658304 299 1283457024 134512640 135304128 4291667696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21612/statm: 649 299 251 194 0 36 0
[pid=21621] ppid=21612 vsize=261032 CPUtime=47.51
/proc/21621/stat : 21621 (clasp) R 21612 21612 17511 34816 17511 4202496 66868 0 0 0 4731 20 0 0 25 0 1 0 46205958 267296768 65015 1283457024 134512640 136285277 4294668720 18446744073709551615 134985125 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21621/statm: 65258 65015 234 433 0 64823 0
Current children cumulated CPU time (s) 50.78
Current children cumulated vsize (KiB) 263628

[startup+102.307 s]
/proc/loadavg: 1.11 1.22 1.11 2/35 21623
/proc/meminfo: memFree=43052/1048576 swapFree=0/0
[pid=21612] ppid=21611 vsize=2596 CPUtime=3.27
/proc/21612/stat : 21612 (aspcud-1.5) S 21611 21612 17511 34816 17511 4202496 586 25555 0 0 0 0 312 15 15 0 1 0 46205957 2658304 299 1283457024 134512640 135304128 4291667696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21612/statm: 649 299 251 194 0 36 0
[pid=21621] ppid=21612 vsize=302252 CPUtime=98.65
/proc/21621/stat : 21621 (clasp) R 21612 21612 17511 34816 17511 4202496 77626 0 0 0 9837 28 0 0 25 0 1 0 46205958 309506048 75329 1283457024 134512640 136285277 4294668720 18446744073709551615 134966730 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21621/statm: 75563 75329 234 433 0 75128 0
Current children cumulated CPU time (s) 101.92
Current children cumulated vsize (KiB) 304848

Solver just ended. Dumping a history of the last processes samples

[startup+102.407 s]
/proc/loadavg: 1.11 1.22 1.11 2/35 21623
/proc/meminfo: memFree=43052/1048576 swapFree=0/0
[pid=21612] ppid=21611 vsize=2596 CPUtime=3.27
/proc/21612/stat : 21612 (aspcud-1.5) S 21611 21612 17511 34816 17511 4202496 586 25555 0 0 0 0 312 15 15 0 1 0 46205957 2658304 299 1283457024 134512640 135304128 4291667696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21612/statm: 649 299 251 194 0 36 0
[pid=21621] ppid=21612 vsize=302252 CPUtime=98.75
/proc/21621/stat : 21621 (clasp) R 21612 21612 17511 34816 17511 4202496 77626 0 0 0 9847 28 0 0 25 0 1 0 46205958 309506048 75329 1283457024 134512640 136285277 4294668720 18446744073709551615 134649408 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21621/statm: 75563 75329 234 433 0 75128 0
Current children cumulated CPU time (s) 102.02
Current children cumulated vsize (KiB) 304848

[startup+108.808 s]
/proc/loadavg: 1.10 1.21 1.11 2/35 21623
/proc/meminfo: memFree=43052/1048576 swapFree=0/0
[pid=21612] ppid=21611 vsize=2596 CPUtime=3.27
/proc/21612/stat : 21612 (aspcud-1.5) S 21611 21612 17511 34816 17511 4202496 586 25555 0 0 0 0 312 15 15 0 1 0 46205957 2658304 299 1283457024 134512640 135304128 4291667696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21612/statm: 649 299 251 194 0 36 0
[pid=21621] ppid=21612 vsize=302252 CPUtime=105.14
/proc/21621/stat : 21621 (clasp) R 21612 21612 17511 34816 17511 4202496 77626 0 0 0 10486 28 0 0 25 0 1 0 46205958 309506048 75329 1283457024 134512640 136285277 4294668720 18446744073709551615 134733711 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21621/statm: 75563 75329 234 433 0 75128 0
Current children cumulated CPU time (s) 108.41
Current children cumulated vsize (KiB) 304848

[startup+112.008 s]
/proc/loadavg: 1.10 1.21 1.11 2/35 21623
/proc/meminfo: memFree=43052/1048576 swapFree=0/0
[pid=21612] ppid=21611 vsize=2596 CPUtime=3.27
/proc/21612/stat : 21612 (aspcud-1.5) S 21611 21612 17511 34816 17511 4202496 586 25555 0 0 0 0 312 15 15 0 1 0 46205957 2658304 299 1283457024 134512640 135304128 4291667696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21612/statm: 649 299 251 194 0 36 0
[pid=21621] ppid=21612 vsize=302252 CPUtime=108.34
/proc/21621/stat : 21621 (clasp) R 21612 21612 17511 34816 17511 4202496 77626 0 0 0 10806 28 0 0 25 0 1 0 46205958 309506048 75329 1283457024 134512640 136285277 4294668720 18446744073709551615 134930821 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21621/statm: 75563 75329 234 433 0 75128 0
Current children cumulated CPU time (s) 111.61
Current children cumulated vsize (KiB) 304848

[startup+113.609 s]
/proc/loadavg: 1.10 1.21 1.11 2/35 21623
/proc/meminfo: memFree=43052/1048576 swapFree=0/0
[pid=21612] ppid=21611 vsize=2596 CPUtime=3.27
/proc/21612/stat : 21612 (aspcud-1.5) S 21611 21612 17511 34816 17511 4202496 586 25555 0 0 0 0 312 15 15 0 1 0 46205957 2658304 299 1283457024 134512640 135304128 4291667696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21612/statm: 649 299 251 194 0 36 0
[pid=21621] ppid=21612 vsize=302252 CPUtime=109.94
/proc/21621/stat : 21621 (clasp) R 21612 21612 17511 34816 17511 4202496 77626 0 0 0 10966 28 0 0 25 0 1 0 46205958 309506048 75329 1283457024 134512640 136285277 4294668720 18446744073709551615 134734261 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21621/statm: 75563 75329 234 433 0 75128 0
Current children cumulated CPU time (s) 113.21
Current children cumulated vsize (KiB) 304848

[startup+114.409 s]
/proc/loadavg: 1.09 1.20 1.11 2/35 21623
/proc/meminfo: memFree=43052/1048576 swapFree=0/0
[pid=21612] ppid=21611 vsize=2596 CPUtime=3.27
/proc/21612/stat : 21612 (aspcud-1.5) S 21611 21612 17511 34816 17511 4202496 586 25555 0 0 0 0 312 15 15 0 1 0 46205957 2658304 299 1283457024 134512640 135304128 4291667696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21612/statm: 649 299 251 194 0 36 0
[pid=21621] ppid=21612 vsize=302252 CPUtime=110.74
/proc/21621/stat : 21621 (clasp) R 21612 21612 17511 34816 17511 4202496 77626 0 0 0 11046 28 0 0 25 0 1 0 46205958 309506048 75329 1283457024 134512640 136285277 4294668720 18446744073709551615 134931880 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21621/statm: 75563 75329 234 433 0 75128 0
Current children cumulated CPU time (s) 114.01
Current children cumulated vsize (KiB) 304848

[startup+115.209 s]
/proc/loadavg: 1.09 1.20 1.11 2/35 21623
/proc/meminfo: memFree=43052/1048576 swapFree=0/0
[pid=21612] ppid=21611 vsize=2596 CPUtime=3.27
/proc/21612/stat : 21612 (aspcud-1.5) S 21611 21612 17511 34816 17511 4202496 586 25555 0 0 0 0 312 15 15 0 1 0 46205957 2658304 299 1283457024 134512640 135304128 4291667696 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21612/statm: 649 299 251 194 0 36 0
[pid=21621] ppid=21612 vsize=302252 CPUtime=111.54
/proc/21621/stat : 21621 (clasp) R 21612 21612 17511 34816 17511 4202496 77626 0 0 0 11126 28 0 0 25 0 1 0 46205958 309506048 75329 1283457024 134512640 136285277 4294668720 18446744073709551615 134723327 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21621/statm: 75563 75329 234 433 0 75128 0
Current children cumulated CPU time (s) 114.81
Current children cumulated vsize (KiB) 304848

[startup+115.409 s]
/proc/loadavg: 1.09 1.20 1.11 2/35 21623
/proc/meminfo: memFree=43052/1048576 swapFree=0/0
[pid=21612] ppid=21611 vsize=2728 CPUtime=115.02
/proc/21612/stat : 21612 (aspcud-1.5) R 21611 21612 17511 34816 17511 4202496 819 105005 0 0 0 1 11451 50 20 0 1 0 46205957 2793472 332 1283457024 134512640 135304128 4291667696 18446744073709551615 4294960130 0 0 16902 1132543225 0 0 0 17 0 0 0 0
/proc/21612/statm: 682 332 256 194 0 69 0
Current children cumulated CPU time (s) 115.02
Current children cumulated vsize (KiB) 2728

Child status: 0
Real time (s): 115.427
CPU time (s): 115.039
CPU user time (s): 114.519
CPU system time (s): 0.520032
CPU usage (%): 99.6645
Max. virtual memory (cumulated for all children) (KiB): 306676

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 114.519
system time used= 0.520032
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 107741
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= 1325
involuntary context switches= 2399

runsolver used 0 second user time and 0 second system time

The end