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/rand214.cudf.s-e-l.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s-e-l/rand214.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand214.cudf.s-e-l.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.06 1.03 1.00 5/37 4446
/proc/meminfo: memFree=582980/1048576 swapFree=0/0
[pid=4444] ppid=4443 vsize=2588 CPUtime=0
/proc/4444/stat : 4444 (aspcud-trendy-1) S 4443 4444 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 1212252 2650112 279 1283457024 134512640 135304128 4288494592 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/4444/statm: 647 279 234 194 0 34 0
[pid=4445] ppid=4444 vsize=2588 CPUtime=0
/proc/4445/stat : 4445 (aspcud-trendy-1) R 4444 4444 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 1212252 2650112 132 1283457024 134512640 135304128 4288494592 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/4445/statm: 647 132 86 194 0 34 0
[pid=4446] ppid=4445 vsize=2588 CPUtime=0
/proc/4446/stat : 4446 (aspcud-trendy-1) R 4445 4444 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 1212253 2650112 46 1283457024 134512640 135304128 4288494592 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/4446/statm: 647 46 0 194 0 34 0

[startup+0.135501 s]
/proc/loadavg: 1.06 1.03 1.00 5/37 4446
/proc/meminfo: memFree=582980/1048576 swapFree=0/0
[pid=4444] ppid=4443 vsize=2596 CPUtime=0
/proc/4444/stat : 4444 (aspcud-trendy-1) S 4443 4444 1511 34817 1511 4202496 623 2230 0 0 0 0 0 0 25 0 1 0 1212252 2658304 298 1283457024 134512640 135304128 4288494592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4444/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.205512 s]
/proc/loadavg: 1.06 1.03 1.00 5/37 4446
/proc/meminfo: memFree=582980/1048576 swapFree=0/0
[pid=4444] ppid=4443 vsize=2596 CPUtime=0
/proc/4444/stat : 4444 (aspcud-trendy-1) S 4443 4444 1511 34817 1511 4202496 623 2230 0 0 0 0 0 0 25 0 1 0 1212252 2658304 298 1283457024 134512640 135304128 4288494592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4444/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.305522 s]
/proc/loadavg: 1.06 1.03 1.00 5/37 4446
/proc/meminfo: memFree=582980/1048576 swapFree=0/0
[pid=4444] ppid=4443 vsize=2596 CPUtime=0
/proc/4444/stat : 4444 (aspcud-trendy-1) S 4443 4444 1511 34817 1511 4202496 623 2230 0 0 0 0 0 0 25 0 1 0 1212252 2658304 298 1283457024 134512640 135304128 4288494592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4444/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.705574 s]
/proc/loadavg: 1.06 1.03 1.00 5/37 4446
/proc/meminfo: memFree=582980/1048576 swapFree=0/0
[pid=4444] ppid=4443 vsize=2596 CPUtime=0
/proc/4444/stat : 4444 (aspcud-trendy-1) S 4443 4444 1511 34817 1511 4202496 623 2230 0 0 0 0 0 0 25 0 1 0 1212252 2658304 298 1283457024 134512640 135304128 4288494592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4444/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.50566 s]
/proc/loadavg: 1.06 1.03 1.00 2/39 4458
/proc/meminfo: memFree=552068/1048576 swapFree=0/0
[pid=4444] ppid=4443 vsize=2596 CPUtime=0
/proc/4444/stat : 4444 (aspcud-trendy-1) S 4443 4444 1511 34817 1511 4202496 623 2230 0 0 0 0 0 0 25 0 1 0 1212252 2658304 298 1283457024 134512640 135304128 4288494592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4444/statm: 649 298 251 194 0 36 0
[pid=4456] ppid=4444 vsize=6500 CPUtime=0.02
/proc/4456/stat : 4456 (clasp) R 4444 4444 1511 34817 1511 4202496 1543 0 0 0 2 0 0 0 18 0 1 0 1212254 6656000 1329 1283457024 134512640 136285277 4286929472 18446744073709551615 135641886 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4456/statm: 1625 1329 177 433 0 1190 0
[pid=4457] ppid=4444 vsize=9016 CPUtime=0.21
/proc/4457/stat : 4457 (gringo) S 4444 4444 1511 34817 1511 4202496 2437 0 0 0 20 1 0 0 18 0 1 0 1212254 9232384 1626 1283457024 134512640 136933539 4287177456 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/4457/statm: 2254 1626 242 592 0 1659 0
[pid=4458] ppid=4444 vsize=30576 CPUtime=1.25
/proc/4458/stat : 4458 (cudf2lp) R 4444 4444 1511 34817 1511 4202496 10055 0 0 0 119 6 0 0 25 0 1 0 1212254 31309824 7426 1283457024 134512640 135786343 4286638192 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/4458/statm: 7644 7426 137 311 0 7331 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 48688

[startup+3.10598 s]
/proc/loadavg: 1.06 1.03 1.00 3/38 4458
/proc/meminfo: memFree=542908/1048576 swapFree=0/0
[pid=4444] ppid=4443 vsize=2596 CPUtime=2.53
/proc/4444/stat : 4444 (aspcud-trendy-1) S 4443 4444 1511 34817 1511 4202496 624 25367 0 0 0 0 241 12 18 0 1 0 1212252 2658304 298 1283457024 134512640 135304128 4288494592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4444/statm: 649 298 251 194 0 36 0
[pid=4456] ppid=4444 vsize=35712 CPUtime=0.57
/proc/4456/stat : 4456 (clasp) R 4444 4444 1511 34817 1511 4202496 10387 0 0 0 56 1 0 0 18 0 1 0 1212254 36569088 8643 1283457024 134512640 136285277 4286929472 18446744073709551615 134889062 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4456/statm: 8928 8643 218 433 0 8493 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 38308

[startup+6.30648 s]
/proc/loadavg: 1.05 1.03 1.00 2/37 4458
/proc/meminfo: memFree=549000/1048576 swapFree=0/0
[pid=4444] ppid=4443 vsize=2596 CPUtime=2.53
/proc/4444/stat : 4444 (aspcud-trendy-1) S 4443 4444 1511 34817 1511 4202496 624 25367 0 0 0 0 241 12 18 0 1 0 1212252 2658304 298 1283457024 134512640 135304128 4288494592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4444/statm: 649 298 251 194 0 36 0
[pid=4456] ppid=4444 vsize=35168 CPUtime=3.77
/proc/4456/stat : 4456 (clasp) R 4444 4444 1511 34817 1511 4202496 10425 0 0 0 375 2 0 0 25 0 1 0 1212254 36012032 8565 1283457024 134512640 136285277 4286929472 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4456/statm: 8792 8565 234 433 0 8357 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 37764

[startup+12.7081 s]
/proc/loadavg: 1.05 1.03 1.00 2/37 4459
/proc/meminfo: memFree=531160/1048576 swapFree=0/0
[pid=4444] ppid=4443 vsize=2596 CPUtime=2.53
/proc/4444/stat : 4444 (aspcud-trendy-1) S 4443 4444 1511 34817 1511 4202496 624 25367 0 0 0 0 241 12 18 0 1 0 1212252 2658304 298 1283457024 134512640 135304128 4288494592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4444/statm: 649 298 251 194 0 36 0
[pid=4456] ppid=4444 vsize=53632 CPUtime=10.17
/proc/4456/stat : 4456 (clasp) R 4444 4444 1511 34817 1511 4202496 15032 0 0 0 1013 4 0 0 25 0 1 0 1212254 54919168 13172 1283457024 134512640 136285277 4286929472 18446744073709551615 134930818 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4456/statm: 13408 13172 234 433 0 12973 0
Current children cumulated CPU time (s) 12.7
Current children cumulated vsize (KiB) 56228

[startup+25.5109 s]
/proc/loadavg: 1.04 1.03 1.00 2/37 4460
/proc/meminfo: memFree=522356/1048576 swapFree=0/0
[pid=4444] ppid=4443 vsize=2596 CPUtime=2.53
/proc/4444/stat : 4444 (aspcud-trendy-1) S 4443 4444 1511 34817 1511 4202496 624 25367 0 0 0 0 241 12 18 0 1 0 1212252 2658304 298 1283457024 134512640 135304128 4288494592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4444/statm: 649 298 251 194 0 36 0
[pid=4456] ppid=4444 vsize=62492 CPUtime=22.96
/proc/4456/stat : 4456 (clasp) R 4444 4444 1511 34817 1511 4202496 17233 0 0 0 2291 5 0 0 25 0 1 0 1212254 63991808 15373 1283457024 134512640 136285277 4286929472 18446744073709551615 134686319 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4456/statm: 15623 15373 234 433 0 15188 0
Current children cumulated CPU time (s) 25.49
Current children cumulated vsize (KiB) 65088

[startup+51.1073 s]
/proc/loadavg: 1.02 1.02 1.00 2/37 4463
/proc/meminfo: memFree=510080/1048576 swapFree=0/0
[pid=4444] ppid=4443 vsize=2596 CPUtime=2.53
/proc/4444/stat : 4444 (aspcud-trendy-1) S 4443 4444 1511 34817 1511 4202496 624 25367 0 0 0 0 241 12 18 0 1 0 1212252 2658304 298 1283457024 134512640 135304128 4288494592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4444/statm: 649 298 251 194 0 36 0
[pid=4456] ppid=4444 vsize=74816 CPUtime=48.54
/proc/4456/stat : 4456 (clasp) R 4444 4444 1511 34817 1511 4202496 20316 0 0 0 4849 5 0 0 25 0 1 0 1212254 76611584 18456 1283457024 134512640 136285277 4286929472 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4456/statm: 18704 18456 234 433 0 18269 0
Current children cumulated CPU time (s) 51.07
Current children cumulated vsize (KiB) 77412

[startup+102.311 s]
/proc/loadavg: 1.01 1.02 1.00 2/36 4464
/proc/meminfo: memFree=386096/1048576 swapFree=0/0
[pid=4444] ppid=4443 vsize=2596 CPUtime=2.53
/proc/4444/stat : 4444 (aspcud-trendy-1) S 4443 4444 1511 34817 1511 4202496 624 25367 0 0 0 0 241 12 18 0 1 0 1212252 2658304 298 1283457024 134512640 135304128 4288494592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4444/statm: 649 298 251 194 0 36 0
[pid=4456] ppid=4444 vsize=198988 CPUtime=99.71
/proc/4456/stat : 4456 (clasp) R 4444 4444 1511 34817 1511 4202496 51379 0 0 0 9947 24 0 0 25 0 1 0 1212254 203763712 49414 1283457024 134512640 136285277 4286929472 18446744073709551615 134960175 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4456/statm: 49747 49414 234 433 0 49312 0
Current children cumulated CPU time (s) 102.24
Current children cumulated vsize (KiB) 201584

[startup+162.31 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 4464
/proc/meminfo: memFree=371596/1048576 swapFree=0/0
[pid=4444] ppid=4443 vsize=2596 CPUtime=2.53
/proc/4444/stat : 4444 (aspcud-trendy-1) S 4443 4444 1511 34817 1511 4202496 624 25367 0 0 0 0 241 12 18 0 1 0 1212252 2658304 298 1283457024 134512640 135304128 4288494592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4444/statm: 649 298 251 194 0 36 0
[pid=4456] ppid=4444 vsize=213516 CPUtime=159.63
/proc/4456/stat : 4456 (clasp) R 4444 4444 1511 34817 1511 4202496 55002 0 0 0 15932 31 0 0 25 0 1 0 1212254 218640384 53037 1283457024 134512640 136285277 4286929472 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4456/statm: 53379 53037 234 433 0 52944 0
Current children cumulated CPU time (s) 162.16
Current children cumulated vsize (KiB) 216112

[startup+222.308 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 4464
/proc/meminfo: memFree=369612/1048576 swapFree=0/0
[pid=4444] ppid=4443 vsize=2596 CPUtime=2.53
/proc/4444/stat : 4444 (aspcud-trendy-1) S 4443 4444 1511 34817 1511 4202496 624 25367 0 0 0 0 241 12 18 0 1 0 1212252 2658304 298 1283457024 134512640 135304128 4288494592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4444/statm: 649 298 251 194 0 36 0
[pid=4456] ppid=4444 vsize=215472 CPUtime=219.59
/proc/4456/stat : 4456 (clasp) R 4444 4444 1511 34817 1511 4202496 55497 0 0 0 21926 33 0 0 25 0 1 0 1212254 220643328 53532 1283457024 134512640 136285277 4286929472 18446744073709551615 134959543 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4456/statm: 53868 53532 234 433 0 53433 0
Current children cumulated CPU time (s) 222.12
Current children cumulated vsize (KiB) 218068

[startup+282.305 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 4464
/proc/meminfo: memFree=369116/1048576 swapFree=0/0
[pid=4444] ppid=4443 vsize=2596 CPUtime=2.53
/proc/4444/stat : 4444 (aspcud-trendy-1) S 4443 4444 1511 34817 1511 4202496 624 25367 0 0 0 0 241 12 18 0 1 0 1212252 2658304 298 1283457024 134512640 135304128 4288494592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4444/statm: 649 298 251 194 0 36 0
[pid=4456] ppid=4444 vsize=215920 CPUtime=279.52
/proc/4456/stat : 4456 (clasp) R 4444 4444 1511 34817 1511 4202496 55598 0 0 0 27919 33 0 0 25 0 1 0 1212254 221102080 53633 1283457024 134512640 136285277 4286929472 18446744073709551615 134985131 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4456/statm: 53980 53633 234 433 0 53545 0
Current children cumulated CPU time (s) 282.05
Current children cumulated vsize (KiB) 218516



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.307 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 4464
/proc/meminfo: memFree=369116/1048576 swapFree=0/0
[pid=4444] ppid=4443 vsize=2596 CPUtime=2.53
/proc/4444/stat : 4444 (aspcud-trendy-1) S 4443 4444 1511 34817 1511 4202496 624 25367 0 0 0 0 241 12 18 0 1 0 1212252 2658304 298 1283457024 134512640 135304128 4288494592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4444/statm: 649 298 251 194 0 36 0
[pid=4456] ppid=4444 vsize=215920 CPUtime=287.51
/proc/4456/stat : 4456 (clasp) R 4444 4444 1511 34817 1511 4202496 55598 0 0 0 28718 33 0 0 25 0 1 0 1212254 221102080 53633 1283457024 134512640 136285277 4286929472 18446744073709551615 134959981 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4456/statm: 53980 53633 234 433 0 53545 0
Current children cumulated CPU time (s) 290.04
Current children cumulated vsize (KiB) 218516

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

Child status: 0
Real time (s): 290.341
CPU time (s): 290.09
CPU user time (s): 289.602
CPU system time (s): 0.48803
CPU usage (%): 99.9136
Max. virtual memory (cumulated for all children) (KiB): 218516

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.602
system time used= 0.48803
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 85226
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= 1251
involuntary context switches= 4327

runsolver used 0 second user time and 0 second system time

The end