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/dd08e73e-d489-11df-b9cf-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/dudf-real//dd08e73e-d489-11df-b9cf-00163e3d3b7c.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/dd08e73e-d489-11df-b9cf-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.34 1.19 1.12 5/36 32662
/proc/meminfo: memFree=290468/1048576 swapFree=0/0
[pid=32659] ppid=32658 vsize=2592 CPUtime=0
/proc/32659/stat : 32659 (aspcud-trendy-1) S 32658 32659 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 5125602 2654208 280 1283457024 134512640 135304128 4289061968 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/32659/statm: 648 280 234 194 0 35 0
[pid=32660] ppid=32659 vsize=2592 CPUtime=0
/proc/32660/stat : 32660 (aspcud-trendy-1) S 32659 32659 1511 34817 1511 4202560 118 0 0 0 0 0 0 0 18 0 1 0 5125602 2654208 134 1283457024 134512640 135304128 4289061968 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/32660/statm: 648 134 87 194 0 35 0
[pid=32661] ppid=32660 vsize=2592 CPUtime=0
/proc/32661/stat : 32661 (aspcud-trendy-1) R 32660 32659 1511 34817 1511 4202560 127 0 0 0 0 0 0 0 25 0 1 0 5125602 2654208 151 1283457024 134512640 135304128 4289061968 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/32661/statm: 648 151 104 194 0 35 0
[pid=32662] ppid=32661 vsize=2592 CPUtime=0
/proc/32662/stat : 32662 (aspcud-trendy-1) R 32661 32659 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 5125602 2654208 47 1283457024 134512640 135304128 4289061968 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/32662/statm: 648 47 0 194 0 35 0

[startup+0.165348 s]
/proc/loadavg: 1.34 1.19 1.12 5/36 32662
/proc/meminfo: memFree=290468/1048576 swapFree=0/0
[pid=32659] ppid=32658 vsize=2600 CPUtime=0.01
/proc/32659/stat : 32659 (aspcud-trendy-1) S 32658 32659 1511 34817 1511 4202496 623 2227 0 0 0 0 0 1 25 0 1 0 5125602 2662400 299 1283457024 134512640 135304128 4289061968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32659/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.205354 s]
/proc/loadavg: 1.34 1.19 1.12 5/36 32662
/proc/meminfo: memFree=290468/1048576 swapFree=0/0
[pid=32659] ppid=32658 vsize=2600 CPUtime=0.01
/proc/32659/stat : 32659 (aspcud-trendy-1) S 32658 32659 1511 34817 1511 4202496 623 2227 0 0 0 0 0 1 25 0 1 0 5125602 2662400 299 1283457024 134512640 135304128 4289061968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32659/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.305382 s]
/proc/loadavg: 1.34 1.19 1.12 5/36 32662
/proc/meminfo: memFree=290468/1048576 swapFree=0/0
[pid=32659] ppid=32658 vsize=2600 CPUtime=0.01
/proc/32659/stat : 32659 (aspcud-trendy-1) S 32658 32659 1511 34817 1511 4202496 623 2227 0 0 0 0 0 1 25 0 1 0 5125602 2662400 299 1283457024 134512640 135304128 4289061968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32659/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.705458 s]
/proc/loadavg: 1.34 1.19 1.12 5/36 32662
/proc/meminfo: memFree=290468/1048576 swapFree=0/0
[pid=32659] ppid=32658 vsize=2600 CPUtime=0.01
/proc/32659/stat : 32659 (aspcud-trendy-1) S 32658 32659 1511 34817 1511 4202496 623 2227 0 0 0 0 0 1 25 0 1 0 5125602 2662400 299 1283457024 134512640 135304128 4289061968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32659/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+1.50587 s]
/proc/loadavg: 1.34 1.19 1.12 2/37 32673
/proc/meminfo: memFree=268252/1048576 swapFree=0/0
[pid=32659] ppid=32658 vsize=2600 CPUtime=0.01
/proc/32659/stat : 32659 (aspcud-trendy-1) S 32658 32659 1511 34817 1511 4202496 623 2227 0 0 0 0 0 1 25 0 1 0 5125602 2662400 299 1283457024 134512640 135304128 4289061968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32659/statm: 650 299 251 194 0 37 0
[pid=32671] ppid=32659 vsize=1924 CPUtime=0
/proc/32671/stat : 32671 (clasp) S 32659 32659 1511 34817 1511 4202496 292 0 0 0 0 0 0 0 25 0 1 0 5125604 1970176 159 1283457024 134512640 136285277 4289760496 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/32671/statm: 481 159 144 433 0 46 0
[pid=32672] ppid=32659 vsize=2584 CPUtime=0
/proc/32672/stat : 32672 (gringo) S 32659 32659 1511 34817 1511 4202496 405 0 0 0 0 0 0 0 25 0 1 0 5125604 2646016 272 1283457024 134512640 136933539 4289787248 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/32672/statm: 646 272 242 592 0 51 0
[pid=32673] ppid=32659 vsize=40276 CPUtime=1.49
/proc/32673/stat : 32673 (cudf2lp) R 32659 32659 1511 34817 1511 4202496 11162 0 0 0 145 4 0 0 25 0 1 0 5125604 41242624 9514 1283457024 134512640 135786343 4291952544 18446744073709551615 134553946 0 0 6 0 0 0 0 17 0 0 0 0
/proc/32673/statm: 10069 9514 133 311 0 9756 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 47384

[startup+3.10617 s]
/proc/loadavg: 1.32 1.18 1.11 2/37 32673
/proc/meminfo: memFree=258208/1048576 swapFree=0/0
[pid=32659] ppid=32658 vsize=2600 CPUtime=1.8
/proc/32659/stat : 32659 (aspcud-trendy-1) R 32658 32659 1511 34817 1511 4202496 624 13409 0 0 0 0 174 6 18 0 1 0 5125602 2662400 299 1283457024 134512640 135304128 4289061968 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0
/proc/32659/statm: 650 299 251 194 0 37 0
[pid=32671] ppid=32659 vsize=30432 CPUtime=0.2
/proc/32671/stat : 32671 (clasp) R 32659 32659 1511 34817 1511 4202496 8095 0 0 0 18 2 0 0 18 0 1 0 5125604 31162368 7101 1283457024 134512640 136285277 4289760496 18446744073709551615 135069411 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32671/statm: 7608 7101 180 433 0 7173 0
[pid=32672] ppid=32659 vsize=0 CPUtime=1.1
/proc/32672/stat : 32672 (gringo) Z 32659 32659 1511 34817 1511 4202508 13279 0 0 0 106 4 0 0 19 0 1 0 5125604 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0
/proc/32672/statm: 0 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 33032

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

[startup+3.2062 s]
/proc/loadavg: 1.32 1.18 1.11 2/37 32673
/proc/meminfo: memFree=258208/1048576 swapFree=0/0
[pid=32659] ppid=32658 vsize=2600 CPUtime=2.9
/proc/32659/stat : 32659 (aspcud-trendy-1) S 32658 32659 1511 34817 1511 4202496 624 26688 0 0 0 0 280 10 18 0 1 0 5125602 2662400 299 1283457024 134512640 135304128 4289061968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32659/statm: 650 299 251 194 0 37 0
[pid=32671] ppid=32659 vsize=31580 CPUtime=0.3
/proc/32671/stat : 32671 (clasp) R 32659 32659 1511 34817 1511 4202496 8489 0 0 0 28 2 0 0 18 0 1 0 5125604 32337920 7495 1283457024 134512640 136285277 4289760496 18446744073709551615 135066291 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32671/statm: 7895 7495 189 433 0 7460 0
Current children cumulated CPU time (s) 3.2
Current children cumulated vsize (KiB) 34180

[startup+4.00637 s]
/proc/loadavg: 1.32 1.18 1.11 2/35 32673
/proc/meminfo: memFree=253900/1048576 swapFree=0/0
[pid=32659] ppid=32658 vsize=2600 CPUtime=2.9
/proc/32659/stat : 32659 (aspcud-trendy-1) S 32658 32659 1511 34817 1511 4202496 624 26688 0 0 0 0 280 10 18 0 1 0 5125602 2662400 299 1283457024 134512640 135304128 4289061968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32659/statm: 650 299 251 194 0 37 0
[pid=32671] ppid=32659 vsize=36608 CPUtime=1.09
/proc/32671/stat : 32671 (clasp) R 32659 32659 1511 34817 1511 4202496 10670 0 0 0 106 3 0 0 18 0 1 0 5125604 37486592 8888 1283457024 134512640 136285277 4289760496 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32671/statm: 9152 8888 234 433 0 8717 0
Current children cumulated CPU time (s) 3.99
Current children cumulated vsize (KiB) 39208

[startup+4.40645 s]
/proc/loadavg: 1.32 1.18 1.11 2/35 32673
/proc/meminfo: memFree=255264/1048576 swapFree=0/0
[pid=32659] ppid=32658 vsize=2600 CPUtime=2.9
/proc/32659/stat : 32659 (aspcud-trendy-1) S 32658 32659 1511 34817 1511 4202496 624 26688 0 0 0 0 280 10 18 0 1 0 5125602 2662400 299 1283457024 134512640 135304128 4289061968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32659/statm: 650 299 251 194 0 37 0
[pid=32671] ppid=32659 vsize=36608 CPUtime=1.49
/proc/32671/stat : 32671 (clasp) R 32659 32659 1511 34817 1511 4202496 10670 0 0 0 146 3 0 0 19 0 1 0 5125604 37486592 8888 1283457024 134512640 136285277 4289760496 18446744073709551615 134717529 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32671/statm: 9152 8888 234 433 0 8717 0
Current children cumulated CPU time (s) 4.39
Current children cumulated vsize (KiB) 39208

[startup+4.80654 s]
/proc/loadavg: 1.32 1.18 1.11 2/35 32673
/proc/meminfo: memFree=255264/1048576 swapFree=0/0
[pid=32659] ppid=32658 vsize=2600 CPUtime=2.9
/proc/32659/stat : 32659 (aspcud-trendy-1) S 32658 32659 1511 34817 1511 4202496 624 26688 0 0 0 0 280 10 18 0 1 0 5125602 2662400 299 1283457024 134512640 135304128 4289061968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32659/statm: 650 299 251 194 0 37 0
[pid=32671] ppid=32659 vsize=36608 CPUtime=1.89
/proc/32671/stat : 32671 (clasp) R 32659 32659 1511 34817 1511 4202496 10670 0 0 0 186 3 0 0 20 0 1 0 5125604 37486592 8888 1283457024 134512640 136285277 4289760496 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32671/statm: 9152 8888 234 433 0 8717 0
Current children cumulated CPU time (s) 4.79
Current children cumulated vsize (KiB) 39208

[startup+4.90658 s]
/proc/loadavg: 1.32 1.18 1.11 2/35 32673
/proc/meminfo: memFree=255264/1048576 swapFree=0/0
[pid=32659] ppid=32658 vsize=2600 CPUtime=2.9
/proc/32659/stat : 32659 (aspcud-trendy-1) S 32658 32659 1511 34817 1511 4202496 624 26688 0 0 0 0 280 10 18 0 1 0 5125602 2662400 299 1283457024 134512640 135304128 4289061968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32659/statm: 650 299 251 194 0 37 0
[pid=32671] ppid=32659 vsize=36608 CPUtime=1.99
/proc/32671/stat : 32671 (clasp) R 32659 32659 1511 34817 1511 4202496 10670 0 0 0 196 3 0 0 20 0 1 0 5125604 37486592 8888 1283457024 134512640 136285277 4289760496 18446744073709551615 134951721 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32671/statm: 9152 8888 234 433 0 8717 0
Current children cumulated CPU time (s) 4.89
Current children cumulated vsize (KiB) 39208

Child status: 0
Real time (s): 4.98606
CPU time (s): 4.97231
CPU user time (s): 4.8163
CPU system time (s): 0.156009
CPU usage (%): 99.7243
Max. virtual memory (cumulated for all children) (KiB): 79808

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.8163
system time used= 0.156009
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 41966
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= 1341
involuntary context switches= 975

runsolver used 0 second user time and 0 second system time

The end