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/4f84e9c6-a79c-11e0-9eb7-00163e1e087d.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//4f84e9c6-a79c-11e0-9eb7-00163e1e087d.cudf /home/misc2010/tmp/201109011757/aspcud-1.5/4f84e9c6-a79c-11e0-9eb7-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.00 1.02 1.00 3/34 29683
/proc/meminfo: memFree=660700/1048576 swapFree=0/0
[pid=29682] ppid=29681 vsize=2588 CPUtime=0
/proc/29682/stat : 29682 (aspcud-1.5) R 29681 29682 22717 34817 22717 4202496 365 0 0 0 0 0 0 0 25 0 1 0 72683620 2650112 279 1283457024 134512640 135304128 4290489680 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/29682/statm: 647 279 234 194 0 34 0
[pid=29683] ppid=29682 vsize=2588 CPUtime=0
/proc/29683/stat : 29683 (aspcud-1.5) R 29682 29682 22717 34817 22717 4202560 0 0 0 0 0 0 0 0 25 0 1 0 72683620 2650112 45 1283457024 134512640 135304128 4290489680 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/29683/statm: 647 45 0 194 0 34 0

[startup+0.127453 s]
/proc/loadavg: 1.00 1.02 1.00 3/34 29683
/proc/meminfo: memFree=660700/1048576 swapFree=0/0
[pid=29682] ppid=29681 vsize=2596 CPUtime=0
/proc/29682/stat : 29682 (aspcud-1.5) S 29681 29682 22717 34817 22717 4202496 575 1522 0 0 0 0 0 0 25 0 1 0 72683620 2658304 298 1283457024 134512640 135304128 4290489680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29682/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.209174 s]
/proc/loadavg: 1.00 1.02 1.00 3/34 29683
/proc/meminfo: memFree=660700/1048576 swapFree=0/0
[pid=29682] ppid=29681 vsize=2596 CPUtime=0
/proc/29682/stat : 29682 (aspcud-1.5) S 29681 29682 22717 34817 22717 4202496 575 1522 0 0 0 0 0 0 25 0 1 0 72683620 2658304 298 1283457024 134512640 135304128 4290489680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29682/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.303454 s]
/proc/loadavg: 1.00 1.02 1.00 3/34 29683
/proc/meminfo: memFree=660700/1048576 swapFree=0/0
[pid=29682] ppid=29681 vsize=2596 CPUtime=0
/proc/29682/stat : 29682 (aspcud-1.5) S 29681 29682 22717 34817 22717 4202496 575 1522 0 0 0 0 0 0 25 0 1 0 72683620 2658304 298 1283457024 134512640 135304128 4290489680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29682/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.703486 s]
/proc/loadavg: 1.00 1.02 1.00 3/34 29683
/proc/meminfo: memFree=660700/1048576 swapFree=0/0
[pid=29682] ppid=29681 vsize=2596 CPUtime=0
/proc/29682/stat : 29682 (aspcud-1.5) S 29681 29682 22717 34817 22717 4202496 575 1522 0 0 0 0 0 0 25 0 1 0 72683620 2658304 298 1283457024 134512640 135304128 4290489680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29682/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.51066 s]
/proc/loadavg: 1.00 1.02 1.00 2/37 29693
/proc/meminfo: memFree=621072/1048576 swapFree=0/0
[pid=29682] ppid=29681 vsize=2596 CPUtime=0
/proc/29682/stat : 29682 (aspcud-1.5) S 29681 29682 22717 34817 22717 4202496 575 1522 0 0 0 0 0 0 25 0 1 0 72683620 2658304 298 1283457024 134512640 135304128 4290489680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29682/statm: 649 298 251 194 0 36 0
[pid=29691] ppid=29682 vsize=1924 CPUtime=0
/proc/29691/stat : 29691 (clasp) S 29682 29682 22717 34817 22717 4202496 291 0 0 0 0 0 0 0 25 0 1 0 72683621 1970176 159 1283457024 134512640 136285277 4289367200 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/29691/statm: 481 159 144 433 0 46 0
[pid=29692] ppid=29682 vsize=2588 CPUtime=0
/proc/29692/stat : 29692 (gringo) S 29682 29682 22717 34817 22717 4202496 404 0 0 0 0 0 0 0 25 0 1 0 72683621 2650112 272 1283457024 134512640 136933539 4293482768 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/29692/statm: 647 272 242 592 0 52 0
[pid=29693] ppid=29682 vsize=29104 CPUtime=1.35
/proc/29693/stat : 29693 (cudf2lp) R 29682 29682 22717 34817 22717 4202496 8545 0 0 0 132 3 0 0 25 0 1 0 72683621 29802496 6842 1283457024 134512640 135786343 4289627424 18446744073709551615 134764361 0 0 6 0 0 0 0 17 0 0 0 0
/proc/29693/statm: 7276 6842 128 311 0 6963 0
Current children cumulated CPU time (s) 1.35
Current children cumulated vsize (KiB) 36212

[startup+3.11107 s]
/proc/loadavg: 1.00 1.02 1.00 3/37 29693
/proc/meminfo: memFree=587820/1048576 swapFree=0/0
[pid=29682] ppid=29681 vsize=2596 CPUtime=2
/proc/29682/stat : 29682 (aspcud-1.5) S 29681 29682 22717 34817 22717 4202496 575 15255 0 0 0 0 192 8 18 0 1 0 72683620 2658304 298 1283457024 134512640 135304128 4290489680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29682/statm: 649 298 251 194 0 36 0
[pid=29691] ppid=29682 vsize=20684 CPUtime=0.12
/proc/29691/stat : 29691 (clasp) R 29682 29682 22717 34817 22717 4202496 5655 0 0 0 10 2 0 0 18 0 1 0 72683621 21180416 4865 1283457024 134512640 136285277 4289367200 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/29691/statm: 5171 4865 177 433 0 4736 0
[pid=29692] ppid=29682 vsize=32292 CPUtime=0.8
/proc/29692/stat : 29692 (gringo) R 29682 29682 22717 34817 22717 4202496 9052 0 0 0 75 5 0 0 18 0 1 0 72683621 33067008 6715 1283457024 134512640 136933539 4293482768 18446744073709551615 134889829 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/29692/statm: 8073 6715 253 592 0 7478 0
Current children cumulated CPU time (s) 2.92
Current children cumulated vsize (KiB) 55572

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

[startup+3.21109 s]
/proc/loadavg: 1.00 1.02 1.00 3/37 29693
/proc/meminfo: memFree=587820/1048576 swapFree=0/0
[pid=29682] ppid=29681 vsize=2596 CPUtime=2
/proc/29682/stat : 29682 (aspcud-1.5) S 29681 29682 22717 34817 22717 4202496 575 15255 0 0 0 0 192 8 18 0 1 0 72683620 2658304 298 1283457024 134512640 135304128 4290489680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29682/statm: 649 298 251 194 0 36 0
[pid=29691] ppid=29682 vsize=21348 CPUtime=0.14
/proc/29691/stat : 29691 (clasp) R 29682 29682 22717 34817 22717 4202496 5820 0 0 0 12 2 0 0 18 0 1 0 72683621 21860352 5030 1283457024 134512640 136285277 4289367200 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/29691/statm: 5337 5030 177 433 0 4902 0
[pid=29692] ppid=29682 vsize=33472 CPUtime=0.89
/proc/29692/stat : 29692 (gringo) R 29682 29682 22717 34817 22717 4202496 9286 0 0 0 83 6 0 0 18 0 1 0 72683621 34275328 6949 1283457024 134512640 136933539 4293482768 18446744073709551615 136138335 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/29692/statm: 8368 6949 253 592 0 7773 0
Current children cumulated CPU time (s) 3.03
Current children cumulated vsize (KiB) 57416

[startup+3.61126 s]
/proc/loadavg: 1.00 1.02 1.00 3/36 29693
/proc/meminfo: memFree=588952/1048576 swapFree=0/0
[pid=29682] ppid=29681 vsize=2596 CPUtime=2
/proc/29682/stat : 29682 (aspcud-1.5) R 29681 29682 22717 34817 22717 4202496 575 15255 0 0 0 0 192 8 18 0 1 0 72683620 2658304 298 1283457024 134512640 135304128 4290489680 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0
/proc/29682/statm: 649 298 251 194 0 36 0
[pid=29691] ppid=29682 vsize=29776 CPUtime=0.24
/proc/29691/stat : 29691 (clasp) R 29682 29682 22717 34817 22717 4202496 8078 0 0 0 22 2 0 0 18 0 1 0 72683621 30490624 7085 1283457024 134512640 136285277 4289367200 18446744073709551615 135058487 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/29691/statm: 7444 7085 187 433 0 7009 0
[pid=29692] ppid=29682 vsize=0 CPUtime=1.18
/proc/29692/stat : 29692 (gringo) Z 29682 29682 22717 34817 22717 4202508 13040 0 0 0 110 8 0 0 19 0 1 0 72683621 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0
/proc/29692/statm: 0 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.42
Current children cumulated vsize (KiB) 32372

[startup+3.81133 s]
/proc/loadavg: 1.00 1.02 1.00 3/36 29693
/proc/meminfo: memFree=588952/1048576 swapFree=0/0
[pid=29682] ppid=29681 vsize=2596 CPUtime=3.19
/proc/29682/stat : 29682 (aspcud-1.5) S 29681 29682 22717 34817 22717 4202496 575 28295 0 0 0 0 303 16 18 0 1 0 72683620 2658304 298 1283457024 134512640 135304128 4290489680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29682/statm: 649 298 251 194 0 36 0
[pid=29691] ppid=29682 vsize=36680 CPUtime=0.44
/proc/29691/stat : 29691 (clasp) R 29682 29682 22717 34817 22717 4202496 10350 0 0 0 41 3 0 0 18 0 1 0 72683621 37560320 8792 1283457024 134512640 136285277 4289367200 18446744073709551615 134807304 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/29691/statm: 9170 8792 208 433 0 8735 0
Current children cumulated CPU time (s) 3.63
Current children cumulated vsize (KiB) 39276

[startup+3.91135 s]
/proc/loadavg: 1.00 1.02 1.00 3/36 29693
/proc/meminfo: memFree=588952/1048576 swapFree=0/0
[pid=29682] ppid=29681 vsize=2596 CPUtime=3.72
/proc/29682/stat : 29682 (aspcud-1.5) R 29681 29682 22717 34817 22717 4202496 1250 44884 0 0 0 0 350 22 18 0 1 0 72683620 2658304 303 1283457024 134512640 135304128 4290489680 18446744073709551615 4294960130 0 65538 16902 1132543225 0 0 0 17 0 0 0 0
/proc/29682/statm: 649 303 256 194 0 36 0
Current children cumulated CPU time (s) 3.72
Current children cumulated vsize (KiB) 2596

Child status: 0
Real time (s): 3.94561
CPU time (s): 3.77624
CPU user time (s): 3.50822
CPU system time (s): 0.268016
CPU usage (%): 95.7072
Max. virtual memory (cumulated for all children) (KiB): 78724

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.50822
system time used= 0.268016
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 55118
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= 1627
involuntary context switches= 1304

runsolver used 0 second user time and 0.012 second system time

The end