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/201109011757/aspcud-1.5/8680dd8a-8600-11e0-b285-00163e1e087d.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//8680dd8a-8600-11e0-b285-00163e1e087d.cudf /home/misc2010/tmp/201109011757/aspcud-1.5/8680dd8a-8600-11e0-b285-00163e1e087d.cudf.dudf-real.result -sum(pin-priority-1),-sum(pin-priority-500),-sum(pin-priority-700),-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.14 1.02 1.00 5/35 421
/proc/meminfo: memFree=430120/1048576 swapFree=0/0
[pid=419] ppid=418 vsize=2584 CPUtime=0
/proc/419/stat : 419 (aspcud-1.5) S 418 419 22717 34817 22717 4202496 372 0 0 0 0 0 0 0 19 0 1 0 73172253 2646016 279 1283457024 134512640 135304128 4292521792 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/419/statm: 646 279 234 194 0 33 0
[pid=420] ppid=419 vsize=2584 CPUtime=0
/proc/420/stat : 420 (aspcud-1.5) R 419 419 22717 34817 22717 4202560 110 0 0 0 0 0 0 0 25 0 1 0 73172253 2646016 132 1283457024 134512640 135304128 4292521792 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/420/statm: 646 132 86 194 0 33 0
[pid=421] ppid=420 vsize=2584 CPUtime=0
/proc/421/stat : 421 (aspcud-1.5) R 420 419 22717 34817 22717 4202560 0 0 0 0 0 0 0 0 25 0 1 0 73172253 2646016 46 1283457024 134512640 135304128 4292521792 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/421/statm: 646 46 0 194 0 33 0

[startup+0.202794 s]
/proc/loadavg: 1.14 1.02 1.00 5/35 421
/proc/meminfo: memFree=430120/1048576 swapFree=0/0
[pid=419] ppid=418 vsize=2592 CPUtime=0
/proc/419/stat : 419 (aspcud-1.5) S 418 419 22717 34817 22717 4202496 575 1522 0 0 0 0 0 0 25 0 1 0 73172253 2654208 298 1283457024 134512640 135304128 4292521792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/419/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.306797 s]
/proc/loadavg: 1.14 1.02 1.00 5/35 421
/proc/meminfo: memFree=430120/1048576 swapFree=0/0
[pid=419] ppid=418 vsize=2592 CPUtime=0
/proc/419/stat : 419 (aspcud-1.5) S 418 419 22717 34817 22717 4202496 575 1522 0 0 0 0 0 0 25 0 1 0 73172253 2654208 298 1283457024 134512640 135304128 4292521792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/419/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.406845 s]
/proc/loadavg: 1.14 1.02 1.00 5/35 421
/proc/meminfo: memFree=430120/1048576 swapFree=0/0
[pid=419] ppid=418 vsize=2592 CPUtime=0
/proc/419/stat : 419 (aspcud-1.5) S 418 419 22717 34817 22717 4202496 575 1522 0 0 0 0 0 0 25 0 1 0 73172253 2654208 298 1283457024 134512640 135304128 4292521792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/419/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.706821 s]
/proc/loadavg: 1.14 1.02 1.00 5/35 421
/proc/meminfo: memFree=430120/1048576 swapFree=0/0
[pid=419] ppid=418 vsize=2592 CPUtime=0
/proc/419/stat : 419 (aspcud-1.5) S 418 419 22717 34817 22717 4202496 575 1522 0 0 0 0 0 0 25 0 1 0 73172253 2654208 298 1283457024 134512640 135304128 4292521792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/419/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.50689 s]
/proc/loadavg: 1.14 1.02 1.00 2/37 430
/proc/meminfo: memFree=389072/1048576 swapFree=0/0
[pid=419] ppid=418 vsize=2592 CPUtime=0
/proc/419/stat : 419 (aspcud-1.5) S 418 419 22717 34817 22717 4202496 575 1522 0 0 0 0 0 0 25 0 1 0 73172253 2654208 298 1283457024 134512640 135304128 4292521792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/419/statm: 648 298 251 194 0 35 0
[pid=428] ppid=419 vsize=1928 CPUtime=0
/proc/428/stat : 428 (clasp) S 419 419 22717 34817 22717 4202496 292 0 0 0 0 0 0 0 25 0 1 0 73172254 1974272 160 1283457024 134512640 136285277 4293410944 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/428/statm: 482 160 144 433 0 47 0
[pid=429] ppid=419 vsize=2584 CPUtime=0
/proc/429/stat : 429 (gringo) S 419 419 22717 34817 22717 4202496 404 0 0 0 0 0 0 0 25 0 1 0 73172254 2646016 272 1283457024 134512640 136933539 4289174768 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/429/statm: 646 272 242 592 0 51 0
[pid=430] ppid=419 vsize=35688 CPUtime=1.33
/proc/430/stat : 430 (cudf2lp) R 419 419 22717 34817 22717 4202496 10049 0 0 0 131 2 0 0 25 0 1 0 73172254 36544512 8451 1283457024 134512640 135786343 4293411008 18446744073709551615 134581931 0 0 6 0 0 0 0 17 0 0 0 0
/proc/430/statm: 8922 8451 133 311 0 8609 0
Current children cumulated CPU time (s) 1.33
Current children cumulated vsize (KiB) 42792

[startup+3.1042 s]
/proc/loadavg: 1.14 1.02 1.00 3/37 430
/proc/meminfo: memFree=354416/1048576 swapFree=0/0
[pid=419] ppid=418 vsize=2592 CPUtime=1.84
/proc/419/stat : 419 (aspcud-1.5) S 418 419 22717 34817 22717 4202496 575 14420 0 0 0 0 179 5 18 0 1 0 73172253 2654208 298 1283457024 134512640 135304128 4292521792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/419/statm: 648 298 251 194 0 35 0
[pid=428] ppid=419 vsize=23528 CPUtime=0.12
/proc/428/stat : 428 (clasp) R 419 419 22717 34817 22717 4202496 6347 0 0 0 12 0 0 0 18 0 1 0 73172254 24092672 5557 1283457024 134512640 136285277 4293410944 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/428/statm: 5882 5557 177 433 0 5447 0
[pid=429] ppid=419 vsize=37228 CPUtime=0.94
/proc/429/stat : 429 (gringo) R 419 419 22717 34817 22717 4202496 9793 0 0 0 92 2 0 0 18 0 1 0 73172254 38121472 7553 1283457024 134512640 136933539 4289174768 18446744073709551615 136183709 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/429/statm: 9307 7553 253 592 0 8712 0
Current children cumulated CPU time (s) 2.9
Current children cumulated vsize (KiB) 63348

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

[startup+3.30427 s]
/proc/loadavg: 1.14 1.02 1.00 3/37 430
/proc/meminfo: memFree=354416/1048576 swapFree=0/0
[pid=419] ppid=418 vsize=2592 CPUtime=2.93
/proc/419/stat : 419 (aspcud-1.5) S 418 419 22717 34817 22717 4202496 575 26715 0 0 0 0 284 9 15 0 1 0 73172253 2654208 298 1283457024 134512640 135304128 4292521792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/419/statm: 648 298 251 194 0 35 0
[pid=428] ppid=419 vsize=27560 CPUtime=0.17
/proc/428/stat : 428 (clasp) R 419 419 22717 34817 22717 4202496 7451 0 0 0 15 2 0 0 18 0 1 0 73172254 28221440 6458 1283457024 134512640 136285277 4293410944 18446744073709551615 134783624 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/428/statm: 6890 6458 186 433 0 6455 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 30152

[startup+4.10446 s]
/proc/loadavg: 1.20 1.04 1.01 2/35 430
/proc/meminfo: memFree=384952/1048576 swapFree=0/0
[pid=419] ppid=418 vsize=2592 CPUtime=2.93
/proc/419/stat : 419 (aspcud-1.5) S 418 419 22717 34817 22717 4202496 575 26715 0 0 0 0 284 9 15 0 1 0 73172253 2654208 298 1283457024 134512640 135304128 4292521792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/419/statm: 648 298 251 194 0 35 0
[pid=428] ppid=419 vsize=32388 CPUtime=0.97
/proc/428/stat : 428 (clasp) R 419 419 22717 34817 22717 4202496 9543 0 0 0 94 3 0 0 19 0 1 0 73172254 33165312 7850 1283457024 134512640 136285277 4293410944 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/428/statm: 8097 7850 234 433 0 7662 0
Current children cumulated CPU time (s) 3.9
Current children cumulated vsize (KiB) 34980

[startup+4.90475 s]
/proc/loadavg: 1.20 1.04 1.01 2/35 430
/proc/meminfo: memFree=379752/1048576 swapFree=0/0
[pid=419] ppid=418 vsize=2592 CPUtime=2.93
/proc/419/stat : 419 (aspcud-1.5) S 418 419 22717 34817 22717 4202496 575 26715 0 0 0 0 284 9 15 0 1 0 73172253 2654208 298 1283457024 134512640 135304128 4292521792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/419/statm: 648 298 251 194 0 35 0
[pid=428] ppid=419 vsize=32388 CPUtime=1.77
/proc/428/stat : 428 (clasp) R 419 419 22717 34817 22717 4202496 9543 0 0 0 174 3 0 0 20 0 1 0 73172254 33165312 7850 1283457024 134512640 136285277 4293410944 18446744073709551615 134720090 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/428/statm: 8097 7850 234 433 0 7662 0
Current children cumulated CPU time (s) 4.7
Current children cumulated vsize (KiB) 34980

[startup+5.1048 s]
/proc/loadavg: 1.20 1.04 1.01 2/35 430
/proc/meminfo: memFree=379752/1048576 swapFree=0/0
[pid=419] ppid=418 vsize=2592 CPUtime=2.93
/proc/419/stat : 419 (aspcud-1.5) S 418 419 22717 34817 22717 4202496 575 26715 0 0 0 0 284 9 15 0 1 0 73172253 2654208 298 1283457024 134512640 135304128 4292521792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/419/statm: 648 298 251 194 0 35 0
[pid=428] ppid=419 vsize=32388 CPUtime=1.97
/proc/428/stat : 428 (clasp) R 419 419 22717 34817 22717 4202496 9543 0 0 0 194 3 0 0 21 0 1 0 73172254 33165312 7850 1283457024 134512640 136285277 4293410944 18446744073709551615 134723339 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/428/statm: 8097 7850 234 433 0 7662 0
Current children cumulated CPU time (s) 4.9
Current children cumulated vsize (KiB) 34980

Child status: 0
Real time (s): 5.16915
CPU time (s): 4.97631
CPU user time (s): 4.8203
CPU system time (s): 0.156009
CPU usage (%): 96.2695
Max. virtual memory (cumulated for all children) (KiB): 73464

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.8203
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= 40407
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= 1379
involuntary context switches= 1107

runsolver used 0 second user time and 0.012 second system time

The end