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/e69a0e36-9ef1-11df-9d4a-00163e46d37a.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//e69a0e36-9ef1-11df-9d4a-00163e46d37a.cudf /home/misc2010/tmp/201109011757/aspcud-1.5/e69a0e36-9ef1-11df-9d4a-00163e46d37a.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: 0.97 0.97 0.99 3/34 4163
/proc/meminfo: memFree=240100/1048576 swapFree=0/0
[pid=4162] ppid=4161 vsize=2588 CPUtime=0
/proc/4162/stat : 4162 (aspcud-1.5) R 4161 4162 22717 34817 22717 4202496 366 0 0 0 0 0 0 0 25 0 1 0 73703826 2650112 280 1283457024 134512640 135304128 4287246912 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/4162/statm: 647 280 234 194 0 34 0
[pid=4163] ppid=4162 vsize=2588 CPUtime=0
/proc/4163/stat : 4163 (aspcud-1.5) R 4162 4162 22717 34817 22717 4202560 0 0 0 0 0 0 0 0 25 0 1 0 73703826 2650112 46 1283457024 134512640 135304128 4287246912 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/4163/statm: 647 46 0 194 0 34 0

[startup+0.146466 s]
/proc/loadavg: 0.97 0.97 0.99 3/34 4163
/proc/meminfo: memFree=240100/1048576 swapFree=0/0
[pid=4162] ppid=4161 vsize=2596 CPUtime=0
/proc/4162/stat : 4162 (aspcud-1.5) S 4161 4162 22717 34817 22717 4202496 580 1518 0 0 0 0 0 0 25 0 1 0 73703826 2658304 299 1283457024 134512640 135304128 4287246912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4162/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.202797 s]
/proc/loadavg: 0.97 0.97 0.99 3/34 4163
/proc/meminfo: memFree=240100/1048576 swapFree=0/0
[pid=4162] ppid=4161 vsize=2596 CPUtime=0
/proc/4162/stat : 4162 (aspcud-1.5) S 4161 4162 22717 34817 22717 4202496 580 1518 0 0 0 0 0 0 25 0 1 0 73703826 2658304 299 1283457024 134512640 135304128 4287246912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4162/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.306784 s]
/proc/loadavg: 0.97 0.97 0.99 3/34 4163
/proc/meminfo: memFree=240100/1048576 swapFree=0/0
[pid=4162] ppid=4161 vsize=2596 CPUtime=0
/proc/4162/stat : 4162 (aspcud-1.5) S 4161 4162 22717 34817 22717 4202496 580 1518 0 0 0 0 0 0 25 0 1 0 73703826 2658304 299 1283457024 134512640 135304128 4287246912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4162/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.708753 s]
/proc/loadavg: 0.97 0.97 0.99 3/34 4163
/proc/meminfo: memFree=240100/1048576 swapFree=0/0
[pid=4162] ppid=4161 vsize=2596 CPUtime=0
/proc/4162/stat : 4162 (aspcud-1.5) S 4161 4162 22717 34817 22717 4202496 580 1518 0 0 0 0 0 0 25 0 1 0 73703826 2658304 299 1283457024 134512640 135304128 4287246912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4162/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.50686 s]
/proc/loadavg: 0.97 0.97 0.99 2/37 4173
/proc/meminfo: memFree=201500/1048576 swapFree=0/0
[pid=4162] ppid=4161 vsize=2596 CPUtime=0
/proc/4162/stat : 4162 (aspcud-1.5) S 4161 4162 22717 34817 22717 4202496 580 1518 0 0 0 0 0 0 25 0 1 0 73703826 2658304 299 1283457024 134512640 135304128 4287246912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4162/statm: 649 299 251 194 0 36 0
[pid=4171] ppid=4162 vsize=1928 CPUtime=0
/proc/4171/stat : 4171 (clasp) S 4162 4162 22717 34817 22717 4202496 292 0 0 0 0 0 0 0 25 0 1 0 73703827 1974272 160 1283457024 134512640 136285277 4292722640 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/4171/statm: 482 160 144 433 0 47 0
[pid=4172] ppid=4162 vsize=2588 CPUtime=0
/proc/4172/stat : 4172 (gringo) S 4162 4162 22717 34817 22717 4202496 404 0 0 0 0 0 0 0 25 0 1 0 73703827 2650112 272 1283457024 134512640 136933539 4286794416 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/4172/statm: 647 272 242 592 0 52 0
[pid=4173] ppid=4162 vsize=26960 CPUtime=1.19
/proc/4173/stat : 4173 (cudf2lp) R 4162 4162 22717 34817 22717 4202496 7846 0 0 0 116 3 0 0 25 0 1 0 73703827 27607040 6199 1283457024 134512640 135786343 4288275408 18446744073709551615 135258478 0 0 6 0 0 0 0 17 0 0 0 0
/proc/4173/statm: 6740 6199 128 311 0 6427 0
Current children cumulated CPU time (s) 1.19
Current children cumulated vsize (KiB) 34072

[startup+3.10729 s]
/proc/loadavg: 0.97 0.97 0.99 2/37 4173
/proc/meminfo: memFree=169688/1048576 swapFree=0/0
[pid=4162] ppid=4161 vsize=2596 CPUtime=1.73
/proc/4162/stat : 4162 (aspcud-1.5) S 4161 4162 22717 34817 22717 4202496 580 13518 0 0 0 0 166 7 18 0 1 0 73703826 2658304 299 1283457024 134512640 135304128 4287246912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4162/statm: 649 299 251 194 0 36 0
[pid=4171] ppid=4162 vsize=22884 CPUtime=0.13
/proc/4171/stat : 4171 (clasp) R 4162 4162 22717 34817 22717 4202496 6338 0 0 0 13 0 0 0 18 0 1 0 73703827 23433216 5345 1283457024 134512640 136285277 4292722640 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4171/statm: 5721 5345 177 433 0 5286 0
[pid=4172] ppid=4162 vsize=42128 CPUtime=0.91
/proc/4172/stat : 4172 (gringo) R 4162 4162 22717 34817 22717 4202496 11231 0 0 0 89 2 0 0 18 0 1 0 73703827 43139072 7515 1283457024 134512640 136933539 4286794416 18446744073709551615 134688056 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4172/statm: 10532 7515 253 592 0 9937 0
Current children cumulated CPU time (s) 2.77
Current children cumulated vsize (KiB) 67608

[startup+6.30921 s]
/proc/loadavg: 1.05 0.99 0.99 2/35 4173
/proc/meminfo: memFree=181756/1048576 swapFree=0/0
[pid=4162] ppid=4161 vsize=2596 CPUtime=2.98
/proc/4162/stat : 4162 (aspcud-1.5) S 4161 4162 22717 34817 22717 4202496 580 27808 0 0 0 0 286 12 18 0 1 0 73703826 2658304 299 1283457024 134512640 135304128 4287246912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4162/statm: 649 299 251 194 0 36 0
[pid=4171] ppid=4162 vsize=39180 CPUtime=3
/proc/4171/stat : 4171 (clasp) R 4162 4162 22717 34817 22717 4202496 11503 0 0 0 298 2 0 0 23 0 1 0 73703827 40120320 9566 1283457024 134512640 136285277 4292722640 18446744073709551615 134963464 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4171/statm: 9795 9566 234 433 0 9360 0
Current children cumulated CPU time (s) 5.98
Current children cumulated vsize (KiB) 41776

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

[startup+6.40922 s]
/proc/loadavg: 1.05 0.99 0.99 2/35 4173
/proc/meminfo: memFree=181756/1048576 swapFree=0/0
[pid=4162] ppid=4161 vsize=2596 CPUtime=2.98
/proc/4162/stat : 4162 (aspcud-1.5) S 4161 4162 22717 34817 22717 4202496 580 27808 0 0 0 0 286 12 18 0 1 0 73703826 2658304 299 1283457024 134512640 135304128 4287246912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4162/statm: 649 299 251 194 0 36 0
[pid=4171] ppid=4162 vsize=39180 CPUtime=3.1
/proc/4171/stat : 4171 (clasp) R 4162 4162 22717 34817 22717 4202496 11503 0 0 0 308 2 0 0 23 0 1 0 73703827 40120320 9566 1283457024 134512640 136285277 4292722640 18446744073709551615 134893116 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4171/statm: 9795 9566 234 433 0 9360 0
Current children cumulated CPU time (s) 6.08
Current children cumulated vsize (KiB) 41776

[startup+8.00968 s]
/proc/loadavg: 1.05 0.99 0.99 2/35 4173
/proc/meminfo: memFree=181756/1048576 swapFree=0/0
[pid=4162] ppid=4161 vsize=2596 CPUtime=2.98
/proc/4162/stat : 4162 (aspcud-1.5) S 4161 4162 22717 34817 22717 4202496 580 27808 0 0 0 0 286 12 18 0 1 0 73703826 2658304 299 1283457024 134512640 135304128 4287246912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4162/statm: 649 299 251 194 0 36 0
[pid=4171] ppid=4162 vsize=40532 CPUtime=4.69
/proc/4171/stat : 4171 (clasp) R 4162 4162 22717 34817 22717 4202496 11832 0 0 0 467 2 0 0 25 0 1 0 73703827 41504768 9895 1283457024 134512640 136285277 4292722640 18446744073709551615 134669565 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4171/statm: 10133 9895 234 433 0 9698 0
Current children cumulated CPU time (s) 7.67
Current children cumulated vsize (KiB) 43128

[startup+8.8099 s]
/proc/loadavg: 1.04 0.99 0.99 2/35 4173
/proc/meminfo: memFree=178408/1048576 swapFree=0/0
[pid=4162] ppid=4161 vsize=2596 CPUtime=2.98
/proc/4162/stat : 4162 (aspcud-1.5) S 4161 4162 22717 34817 22717 4202496 580 27808 0 0 0 0 286 12 18 0 1 0 73703826 2658304 299 1283457024 134512640 135304128 4287246912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4162/statm: 649 299 251 194 0 36 0
[pid=4171] ppid=4162 vsize=43080 CPUtime=5.49
/proc/4171/stat : 4171 (clasp) R 4162 4162 22717 34817 22717 4202496 12465 0 0 0 547 2 0 0 25 0 1 0 73703827 44113920 10528 1283457024 134512640 136285277 4292722640 18446744073709551615 134959938 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4171/statm: 10770 10528 234 433 0 10335 0
Current children cumulated CPU time (s) 8.47
Current children cumulated vsize (KiB) 45676

[startup+9.21006 s]
/proc/loadavg: 1.04 0.99 0.99 2/35 4173
/proc/meminfo: memFree=178408/1048576 swapFree=0/0
[pid=4162] ppid=4161 vsize=2596 CPUtime=2.98
/proc/4162/stat : 4162 (aspcud-1.5) S 4161 4162 22717 34817 22717 4202496 580 27808 0 0 0 0 286 12 18 0 1 0 73703826 2658304 299 1283457024 134512640 135304128 4287246912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4162/statm: 649 299 251 194 0 36 0
[pid=4171] ppid=4162 vsize=46224 CPUtime=5.89
/proc/4171/stat : 4171 (clasp) R 4162 4162 22717 34817 22717 4202496 13258 0 0 0 587 2 0 0 25 0 1 0 73703827 47333376 11321 1283457024 134512640 136285277 4292722640 18446744073709551615 134955202 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4171/statm: 11556 11321 234 433 0 11121 0
Current children cumulated CPU time (s) 8.87
Current children cumulated vsize (KiB) 48820

[startup+9.41014 s]
/proc/loadavg: 1.04 0.99 0.99 2/35 4173
/proc/meminfo: memFree=178408/1048576 swapFree=0/0
[pid=4162] ppid=4161 vsize=2596 CPUtime=2.98
/proc/4162/stat : 4162 (aspcud-1.5) S 4161 4162 22717 34817 22717 4202496 580 27808 0 0 0 0 286 12 18 0 1 0 73703826 2658304 299 1283457024 134512640 135304128 4287246912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4162/statm: 649 299 251 194 0 36 0
[pid=4171] ppid=4162 vsize=46904 CPUtime=6.09
/proc/4171/stat : 4171 (clasp) R 4162 4162 22717 34817 22717 4202496 13417 0 0 0 606 3 0 0 25 0 1 0 73703827 48029696 11480 1283457024 134512640 136285277 4292722640 18446744073709551615 134623821 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4171/statm: 11726 11480 234 433 0 11291 0
Current children cumulated CPU time (s) 9.07
Current children cumulated vsize (KiB) 49500

[startup+9.51017 s]
/proc/loadavg: 1.04 0.99 0.99 2/35 4173
/proc/meminfo: memFree=178408/1048576 swapFree=0/0
[pid=4162] ppid=4161 vsize=2596 CPUtime=2.98
/proc/4162/stat : 4162 (aspcud-1.5) S 4161 4162 22717 34817 22717 4202496 580 27808 0 0 0 0 286 12 18 0 1 0 73703826 2658304 299 1283457024 134512640 135304128 4287246912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4162/statm: 649 299 251 194 0 36 0
[pid=4171] ppid=4162 vsize=32636 CPUtime=6.19
/proc/4171/stat : 4171 (clasp) R 4162 4162 22717 34817 22717 4202496 13425 0 0 0 616 3 0 0 25 0 1 0 73703827 33419264 7943 1283457024 134512640 136285277 4292722640 18446744073709551615 135631751 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4171/statm: 8159 7943 242 433 0 7724 0
Current children cumulated CPU time (s) 9.17
Current children cumulated vsize (KiB) 35232

Child status: 0
Real time (s): 9.53905
CPU time (s): 9.20858
CPU user time (s): 9.02456
CPU system time (s): 0.184011
CPU usage (%): 96.5355
Max. virtual memory (cumulated for all children) (KiB): 83744

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 9.02456
system time used= 0.184011
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 45370
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= 1689
involuntary context switches= 1381

runsolver used 0 second user time and 0.008 second system time

The end