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/201108241238/aspcud-trendy-1.5/6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/dudf-real//6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf.dudf-real.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.10 1.12 1.10 5/38 26458
/proc/meminfo: memFree=343052/1048576 swapFree=0/0
[pid=26455] ppid=26454 vsize=2584 CPUtime=0
/proc/26455/stat : 26455 (aspcud-trendy-1) S 26454 26455 1511 34817 1511 4202496 372 0 0 0 0 0 0 0 18 0 1 0 4826866 2646016 279 1283457024 134512640 135304128 4287843104 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/26455/statm: 646 279 234 194 0 33 0
[pid=26456] ppid=26455 vsize=2584 CPUtime=0
/proc/26456/stat : 26456 (aspcud-trendy-1) S 26455 26455 1511 34817 1511 4202560 118 0 0 0 0 0 0 0 18 0 1 0 4826866 2646016 133 1283457024 134512640 135304128 4287843104 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/26456/statm: 646 133 87 194 0 33 0
[pid=26457] ppid=26456 vsize=2584 CPUtime=0
/proc/26457/stat : 26457 (aspcud-trendy-1) R 26456 26455 1511 34817 1511 4202560 126 0 0 0 0 0 0 0 25 0 1 0 4826866 2646016 150 1283457024 134512640 135304128 4287843104 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/26457/statm: 646 150 104 194 0 33 0
[pid=26458] ppid=26457 vsize=2584 CPUtime=0
/proc/26458/stat : 26458 (aspcud-trendy-1) R 26457 26455 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 4826866 2646016 46 1283457024 134512640 135304128 4287843104 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/26458/statm: 646 46 0 194 0 33 0

[startup+0.175288 s]
/proc/loadavg: 1.10 1.12 1.10 5/38 26458
/proc/meminfo: memFree=343052/1048576 swapFree=0/0
[pid=26455] ppid=26454 vsize=2592 CPUtime=0
/proc/26455/stat : 26455 (aspcud-trendy-1) S 26454 26455 1511 34817 1511 4202496 622 2230 0 0 0 0 0 0 25 0 1 0 4826866 2654208 298 1283457024 134512640 135304128 4287843104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26455/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.205291 s]
/proc/loadavg: 1.10 1.12 1.10 5/38 26458
/proc/meminfo: memFree=343052/1048576 swapFree=0/0
[pid=26455] ppid=26454 vsize=2592 CPUtime=0
/proc/26455/stat : 26455 (aspcud-trendy-1) S 26454 26455 1511 34817 1511 4202496 622 2230 0 0 0 0 0 0 25 0 1 0 4826866 2654208 298 1283457024 134512640 135304128 4287843104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26455/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.30532 s]
/proc/loadavg: 1.10 1.12 1.10 5/38 26458
/proc/meminfo: memFree=343052/1048576 swapFree=0/0
[pid=26455] ppid=26454 vsize=2592 CPUtime=0
/proc/26455/stat : 26455 (aspcud-trendy-1) S 26454 26455 1511 34817 1511 4202496 622 2230 0 0 0 0 0 0 25 0 1 0 4826866 2654208 298 1283457024 134512640 135304128 4287843104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26455/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.705399 s]
/proc/loadavg: 1.10 1.12 1.10 5/38 26458
/proc/meminfo: memFree=343052/1048576 swapFree=0/0
[pid=26455] ppid=26454 vsize=2592 CPUtime=0
/proc/26455/stat : 26455 (aspcud-trendy-1) S 26454 26455 1511 34817 1511 4202496 622 2230 0 0 0 0 0 0 25 0 1 0 4826866 2654208 298 1283457024 134512640 135304128 4287843104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26455/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.50558 s]
/proc/loadavg: 1.10 1.12 1.10 2/39 26469
/proc/meminfo: memFree=320588/1048576 swapFree=0/0
[pid=26455] ppid=26454 vsize=2592 CPUtime=0
/proc/26455/stat : 26455 (aspcud-trendy-1) S 26454 26455 1511 34817 1511 4202496 622 2230 0 0 0 0 0 0 25 0 1 0 4826866 2654208 298 1283457024 134512640 135304128 4287843104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26455/statm: 648 298 251 194 0 35 0
[pid=26467] ppid=26455 vsize=1932 CPUtime=0
/proc/26467/stat : 26467 (clasp) S 26455 26455 1511 34817 1511 4202496 292 0 0 0 0 0 0 0 25 0 1 0 4826867 1978368 160 1283457024 134512640 136285277 4287599328 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/26467/statm: 483 160 144 433 0 48 0
[pid=26468] ppid=26455 vsize=2584 CPUtime=0
/proc/26468/stat : 26468 (gringo) S 26455 26455 1511 34817 1511 4202496 404 0 0 0 0 0 0 0 25 0 1 0 4826867 2646016 272 1283457024 134512640 136933539 4292140976 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/26468/statm: 646 272 242 592 0 51 0
[pid=26469] ppid=26455 vsize=33832 CPUtime=1.49
/proc/26469/stat : 26469 (cudf2lp) R 26455 26455 1511 34817 1511 4202496 9770 0 0 0 145 4 0 0 25 0 1 0 4826867 34643968 8026 1283457024 134512640 135786343 4294142384 18446744073709551615 134547133 0 0 6 0 0 0 0 17 0 0 0 0
/proc/26469/statm: 8458 8026 133 311 0 8145 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 40940

[startup+3.106 s]
/proc/loadavg: 1.10 1.12 1.10 3/39 26469
/proc/meminfo: memFree=291076/1048576 swapFree=0/0
[pid=26455] ppid=26454 vsize=2592 CPUtime=1.98
/proc/26455/stat : 26455 (aspcud-trendy-1) S 26454 26455 1511 34817 1511 4202496 623 14457 0 0 0 0 189 9 18 0 1 0 4826866 2654208 298 1283457024 134512640 135304128 4287843104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26455/statm: 648 298 251 194 0 35 0
[pid=26467] ppid=26455 vsize=25548 CPUtime=0.07
/proc/26467/stat : 26467 (clasp) R 26455 26455 1511 34817 1511 4202496 7166 0 0 0 5 2 0 0 18 0 1 0 4826867 26161152 5970 1283457024 134512640 136285277 4287599328 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/26467/statm: 6387 5970 177 433 0 5952 0
[pid=26468] ppid=26455 vsize=43724 CPUtime=1.02
/proc/26468/stat : 26468 (gringo) R 26455 26455 1511 34817 1511 4202496 12158 0 0 0 96 6 0 0 18 0 1 0 4826867 44773376 8393 1283457024 134512640 136933539 4292140976 18446744073709551615 134688156 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/26468/statm: 10931 8393 253 592 0 10336 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 71864

[startup+6.30708 s]
/proc/loadavg: 1.09 1.12 1.10 2/37 26470
/proc/meminfo: memFree=300664/1048576 swapFree=0/0
[pid=26455] ppid=26454 vsize=2592 CPUtime=3.45
/proc/26455/stat : 26455 (aspcud-trendy-1) S 26454 26455 1511 34817 1511 4202496 623 29547 0 0 0 0 327 18 18 0 1 0 4826866 2654208 298 1283457024 134512640 135304128 4287843104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26455/statm: 648 298 251 194 0 35 0
[pid=26467] ppid=26455 vsize=43824 CPUtime=2.85
/proc/26467/stat : 26467 (clasp) R 26455 26455 1511 34817 1511 4202496 13141 0 0 0 280 5 0 0 22 0 1 0 4826867 44875776 10702 1283457024 134512640 136285277 4287599328 18446744073709551615 134686800 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/26467/statm: 10956 10702 234 433 0 10521 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 46416

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

[startup+6.4071 s]
/proc/loadavg: 1.09 1.12 1.10 2/37 26470
/proc/meminfo: memFree=300664/1048576 swapFree=0/0
[pid=26455] ppid=26454 vsize=2592 CPUtime=3.45
/proc/26455/stat : 26455 (aspcud-trendy-1) S 26454 26455 1511 34817 1511 4202496 623 29547 0 0 0 0 327 18 18 0 1 0 4826866 2654208 298 1283457024 134512640 135304128 4287843104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26455/statm: 648 298 251 194 0 35 0
[pid=26467] ppid=26455 vsize=43824 CPUtime=2.95
/proc/26467/stat : 26467 (clasp) R 26455 26455 1511 34817 1511 4202496 13141 0 0 0 290 5 0 0 23 0 1 0 4826867 44875776 10702 1283457024 134512640 136285277 4287599328 18446744073709551615 134669522 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/26467/statm: 10956 10702 234 433 0 10521 0
Current children cumulated CPU time (s) 6.4
Current children cumulated vsize (KiB) 46416

[startup+8.00766 s]
/proc/loadavg: 1.09 1.12 1.10 2/37 26470
/proc/meminfo: memFree=300664/1048576 swapFree=0/0
[pid=26455] ppid=26454 vsize=2592 CPUtime=3.45
/proc/26455/stat : 26455 (aspcud-trendy-1) S 26454 26455 1511 34817 1511 4202496 623 29547 0 0 0 0 327 18 18 0 1 0 4826866 2654208 298 1283457024 134512640 135304128 4287843104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26455/statm: 648 298 251 194 0 35 0
[pid=26467] ppid=26455 vsize=43824 CPUtime=4.55
/proc/26467/stat : 26467 (clasp) R 26455 26455 1511 34817 1511 4202496 13141 0 0 0 450 5 0 0 25 0 1 0 4826867 44875776 10702 1283457024 134512640 136285277 4287599328 18446744073709551615 134893162 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/26467/statm: 10956 10702 234 433 0 10521 0
Current children cumulated CPU time (s) 8
Current children cumulated vsize (KiB) 46416

[startup+8.80794 s]
/proc/loadavg: 1.09 1.12 1.10 2/37 26470
/proc/meminfo: memFree=300672/1048576 swapFree=0/0
[pid=26455] ppid=26454 vsize=2592 CPUtime=3.45
/proc/26455/stat : 26455 (aspcud-trendy-1) S 26454 26455 1511 34817 1511 4202496 623 29547 0 0 0 0 327 18 18 0 1 0 4826866 2654208 298 1283457024 134512640 135304128 4287843104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26455/statm: 648 298 251 194 0 35 0
[pid=26467] ppid=26455 vsize=43824 CPUtime=5.35
/proc/26467/stat : 26467 (clasp) R 26455 26455 1511 34817 1511 4202496 13141 0 0 0 530 5 0 0 25 0 1 0 4826867 44875776 10702 1283457024 134512640 136285277 4287599328 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/26467/statm: 10956 10702 234 433 0 10521 0
Current children cumulated CPU time (s) 8.8
Current children cumulated vsize (KiB) 46416

[startup+9.20808 s]
/proc/loadavg: 1.09 1.12 1.10 2/37 26470
/proc/meminfo: memFree=300672/1048576 swapFree=0/0
[pid=26455] ppid=26454 vsize=2592 CPUtime=3.45
/proc/26455/stat : 26455 (aspcud-trendy-1) S 26454 26455 1511 34817 1511 4202496 623 29547 0 0 0 0 327 18 18 0 1 0 4826866 2654208 298 1283457024 134512640 135304128 4287843104 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26455/statm: 648 298 251 194 0 35 0
[pid=26467] ppid=26455 vsize=43824 CPUtime=5.75
/proc/26467/stat : 26467 (clasp) R 26455 26455 1511 34817 1511 4202496 13141 0 0 0 570 5 0 0 25 0 1 0 4826867 44875776 10702 1283457024 134512640 136285277 4287599328 18446744073709551615 134669522 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/26467/statm: 10956 10702 234 433 0 10521 0
Current children cumulated CPU time (s) 9.2
Current children cumulated vsize (KiB) 46416

Child status: 0
Real time (s): 9.27659
CPU time (s): 9.26858
CPU user time (s): 9.01256
CPU system time (s): 0.256016
CPU usage (%): 99.9136
Max. virtual memory (cumulated for all children) (KiB): 87708

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 9.01256
system time used= 0.256016
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 47292
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= 1905
involuntary context switches= 1526

runsolver used 0 second user time and 0 second system time

The end