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/5698a62c-c731-11df-9bb9-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//5698a62c-c731-11df-9bb9-00163e3d3b7c.cudf /home/misc2010/tmp/201109011757/aspcud-1.5/5698a62c-c731-11df-9bb9-00163e3d3b7c.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.01 1.05 1.02 3/34 30179
/proc/meminfo: memFree=580868/1048576 swapFree=0/0
[pid=30178] ppid=30177 vsize=2592 CPUtime=0
/proc/30178/stat : 30178 (aspcud-1.5) R 30177 30178 22717 34817 22717 4202496 367 0 0 0 0 0 0 0 25 0 1 0 72723613 2654208 280 1283457024 134512640 135304128 4287570576 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/30178/statm: 648 280 234 194 0 35 0
[pid=30179] ppid=30178 vsize=2592 CPUtime=0
/proc/30179/stat : 30179 (aspcud-1.5) R 30178 30178 22717 34817 22717 4202560 0 0 0 0 0 0 0 0 25 0 1 0 72723614 2654208 46 1283457024 134512640 135304128 4287570576 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/30179/statm: 648 46 0 194 0 35 0

[startup+0.146732 s]
/proc/loadavg: 1.01 1.05 1.02 3/34 30179
/proc/meminfo: memFree=580868/1048576 swapFree=0/0
[pid=30178] ppid=30177 vsize=2600 CPUtime=0.01
/proc/30178/stat : 30178 (aspcud-1.5) S 30177 30178 22717 34817 22717 4202496 581 1522 0 0 0 1 0 0 25 0 1 0 72723613 2662400 299 1283457024 134512640 135304128 4287570576 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30178/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.206734 s]
/proc/loadavg: 1.01 1.05 1.02 3/34 30179
/proc/meminfo: memFree=580868/1048576 swapFree=0/0
[pid=30178] ppid=30177 vsize=2600 CPUtime=0.01
/proc/30178/stat : 30178 (aspcud-1.5) S 30177 30178 22717 34817 22717 4202496 581 1522 0 0 0 1 0 0 25 0 1 0 72723613 2662400 299 1283457024 134512640 135304128 4287570576 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30178/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.306744 s]
/proc/loadavg: 1.01 1.05 1.02 3/34 30179
/proc/meminfo: memFree=580868/1048576 swapFree=0/0
[pid=30178] ppid=30177 vsize=2600 CPUtime=0.01
/proc/30178/stat : 30178 (aspcud-1.5) S 30177 30178 22717 34817 22717 4202496 581 1522 0 0 0 1 0 0 25 0 1 0 72723613 2662400 299 1283457024 134512640 135304128 4287570576 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30178/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.708207 s]
/proc/loadavg: 1.01 1.05 1.02 3/34 30179
/proc/meminfo: memFree=580868/1048576 swapFree=0/0
[pid=30178] ppid=30177 vsize=2600 CPUtime=0.01
/proc/30178/stat : 30178 (aspcud-1.5) S 30177 30178 22717 34817 22717 4202496 581 1522 0 0 0 1 0 0 25 0 1 0 72723613 2662400 299 1283457024 134512640 135304128 4287570576 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30178/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+1.50681 s]
/proc/loadavg: 1.01 1.05 1.02 2/37 30189
/proc/meminfo: memFree=541696/1048576 swapFree=0/0
[pid=30178] ppid=30177 vsize=2600 CPUtime=0.01
/proc/30178/stat : 30178 (aspcud-1.5) S 30177 30178 22717 34817 22717 4202496 581 1522 0 0 0 1 0 0 25 0 1 0 72723613 2662400 299 1283457024 134512640 135304128 4287570576 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30178/statm: 650 299 251 194 0 37 0
[pid=30187] ppid=30178 vsize=1928 CPUtime=0
/proc/30187/stat : 30187 (clasp) S 30178 30178 22717 34817 22717 4202496 292 0 0 0 0 0 0 0 25 0 1 0 72723615 1974272 160 1283457024 134512640 136285277 4292964368 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/30187/statm: 482 160 144 433 0 47 0
[pid=30188] ppid=30178 vsize=2584 CPUtime=0
/proc/30188/stat : 30188 (gringo) S 30178 30178 22717 34817 22717 4202496 404 0 0 0 0 0 0 0 25 0 1 0 72723615 2646016 272 1283457024 134512640 136933539 4291616576 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/30188/statm: 646 272 242 592 0 51 0
[pid=30189] ppid=30178 vsize=27972 CPUtime=1.3
/proc/30189/stat : 30189 (cudf2lp) R 30178 30178 22717 34817 22717 4202496 8216 0 0 0 127 3 0 0 25 0 1 0 72723615 28643328 6472 1283457024 134512640 135786343 4289961328 18446744073709551615 135208471 0 0 6 0 0 0 0 17 0 0 0 0
/proc/30189/statm: 6993 6472 128 311 0 6680 0
Current children cumulated CPU time (s) 1.31
Current children cumulated vsize (KiB) 35084

[startup+3.11255 s]
/proc/loadavg: 1.01 1.05 1.02 3/37 30189
/proc/meminfo: memFree=508588/1048576 swapFree=0/0
[pid=30178] ppid=30177 vsize=2600 CPUtime=1.95
/proc/30178/stat : 30178 (aspcud-1.5) S 30177 30178 22717 34817 22717 4202496 581 14394 0 0 0 1 188 6 18 0 1 0 72723613 2662400 299 1283457024 134512640 135304128 4287570576 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30178/statm: 650 299 251 194 0 37 0
[pid=30187] ppid=30178 vsize=21964 CPUtime=0.11
/proc/30187/stat : 30187 (clasp) R 30178 30178 22717 34817 22717 4202496 6095 0 0 0 9 2 0 0 18 0 1 0 72723615 22491136 5102 1283457024 134512640 136285277 4292964368 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/30187/statm: 5491 5102 177 433 0 5056 0
[pid=30188] ppid=30178 vsize=34416 CPUtime=0.81
/proc/30188/stat : 30188 (gringo) R 30178 30178 22717 34817 22717 4202496 9379 0 0 0 79 2 0 0 18 0 1 0 72723615 35241984 7170 1283457024 134512640 136933539 4291616576 18446744073709551615 134889883 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/30188/statm: 8604 7170 253 592 0 8009 0
Current children cumulated CPU time (s) 2.87
Current children cumulated vsize (KiB) 58980

[startup+6.30318 s]
/proc/loadavg: 1.01 1.05 1.01 2/35 30189
/proc/meminfo: memFree=520904/1048576 swapFree=0/0
[pid=30178] ppid=30177 vsize=2600 CPUtime=3.21
/proc/30178/stat : 30178 (aspcud-1.5) S 30177 30178 22717 34817 22717 4202496 581 28376 0 0 0 1 311 9 18 0 1 0 72723613 2662400 299 1283457024 134512640 135304128 4287570576 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30178/statm: 650 299 251 194 0 37 0
[pid=30187] ppid=30178 vsize=39096 CPUtime=2.86
/proc/30187/stat : 30187 (clasp) R 30178 30178 22717 34817 22717 4202496 11476 0 0 0 284 2 0 0 22 0 1 0 72723615 40034304 9545 1283457024 134512640 136285277 4292964368 18446744073709551615 134930836 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/30187/statm: 9774 9545 234 433 0 9339 0
Current children cumulated CPU time (s) 6.07
Current children cumulated vsize (KiB) 41696

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

[startup+6.41323 s]
/proc/loadavg: 1.01 1.05 1.01 2/35 30189
/proc/meminfo: memFree=520904/1048576 swapFree=0/0
[pid=30178] ppid=30177 vsize=2600 CPUtime=3.21
/proc/30178/stat : 30178 (aspcud-1.5) S 30177 30178 22717 34817 22717 4202496 581 28376 0 0 0 1 311 9 18 0 1 0 72723613 2662400 299 1283457024 134512640 135304128 4287570576 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30178/statm: 650 299 251 194 0 37 0
[pid=30187] ppid=30178 vsize=39096 CPUtime=2.97
/proc/30187/stat : 30187 (clasp) R 30178 30178 22717 34817 22717 4202496 11476 0 0 0 295 2 0 0 23 0 1 0 72723615 40034304 9545 1283457024 134512640 136285277 4292964368 18446744073709551615 134628495 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/30187/statm: 9774 9545 234 433 0 9339 0
Current children cumulated CPU time (s) 6.18
Current children cumulated vsize (KiB) 41696

[startup+8.01355 s]
/proc/loadavg: 1.01 1.05 1.01 2/35 30189
/proc/meminfo: memFree=520904/1048576 swapFree=0/0
[pid=30178] ppid=30177 vsize=2600 CPUtime=3.21
/proc/30178/stat : 30178 (aspcud-1.5) S 30177 30178 22717 34817 22717 4202496 581 28376 0 0 0 1 311 9 18 0 1 0 72723613 2662400 299 1283457024 134512640 135304128 4287570576 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30178/statm: 650 299 251 194 0 37 0
[pid=30187] ppid=30178 vsize=39096 CPUtime=4.57
/proc/30187/stat : 30187 (clasp) R 30178 30178 22717 34817 22717 4202496 11476 0 0 0 455 2 0 0 25 0 1 0 72723615 40034304 9545 1283457024 134512640 136285277 4292964368 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/30187/statm: 9774 9545 234 433 0 9339 0
Current children cumulated CPU time (s) 7.78
Current children cumulated vsize (KiB) 41696

[startup+8.81371 s]
/proc/loadavg: 1.01 1.05 1.01 2/35 30189
/proc/meminfo: memFree=520904/1048576 swapFree=0/0
[pid=30178] ppid=30177 vsize=2600 CPUtime=3.21
/proc/30178/stat : 30178 (aspcud-1.5) S 30177 30178 22717 34817 22717 4202496 581 28376 0 0 0 1 311 9 18 0 1 0 72723613 2662400 299 1283457024 134512640 135304128 4287570576 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30178/statm: 650 299 251 194 0 37 0
[pid=30187] ppid=30178 vsize=39096 CPUtime=5.37
/proc/30187/stat : 30187 (clasp) R 30178 30178 22717 34817 22717 4202496 11476 0 0 0 535 2 0 0 25 0 1 0 72723615 40034304 9545 1283457024 134512640 136285277 4292964368 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/30187/statm: 9774 9545 234 433 0 9339 0
Current children cumulated CPU time (s) 8.58
Current children cumulated vsize (KiB) 41696

[startup+9.21379 s]
/proc/loadavg: 1.01 1.05 1.01 2/35 30189
/proc/meminfo: memFree=520904/1048576 swapFree=0/0
[pid=30178] ppid=30177 vsize=2600 CPUtime=3.21
/proc/30178/stat : 30178 (aspcud-1.5) S 30177 30178 22717 34817 22717 4202496 581 28376 0 0 0 1 311 9 18 0 1 0 72723613 2662400 299 1283457024 134512640 135304128 4287570576 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30178/statm: 650 299 251 194 0 37 0
[pid=30187] ppid=30178 vsize=39096 CPUtime=5.77
/proc/30187/stat : 30187 (clasp) R 30178 30178 22717 34817 22717 4202496 11476 0 0 0 575 2 0 0 25 0 1 0 72723615 40034304 9545 1283457024 134512640 136285277 4292964368 18446744073709551615 134931485 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/30187/statm: 9774 9545 234 433 0 9339 0
Current children cumulated CPU time (s) 8.98
Current children cumulated vsize (KiB) 41696

[startup+9.3038 s]
/proc/loadavg: 1.01 1.05 1.01 2/35 30189
/proc/meminfo: memFree=520904/1048576 swapFree=0/0
[pid=30178] ppid=30177 vsize=2600 CPUtime=3.21
/proc/30178/stat : 30178 (aspcud-1.5) S 30177 30178 22717 34817 22717 4202496 581 28376 0 0 0 1 311 9 18 0 1 0 72723613 2662400 299 1283457024 134512640 135304128 4287570576 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/30178/statm: 650 299 251 194 0 37 0
[pid=30187] ppid=30178 vsize=39096 CPUtime=5.86
/proc/30187/stat : 30187 (clasp) R 30178 30178 22717 34817 22717 4202496 11476 0 0 0 584 2 0 0 25 0 1 0 72723615 40034304 9545 1283457024 134512640 136285277 4292964368 18446744073709551615 134966690 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/30187/statm: 9774 9545 234 433 0 9339 0
Current children cumulated CPU time (s) 9.07
Current children cumulated vsize (KiB) 41696

Child status: 0
Real time (s): 9.38301
CPU time (s): 9.16057
CPU user time (s): 9.01656
CPU system time (s): 0.144009
CPU usage (%): 97.6294
Max. virtual memory (cumulated for all children) (KiB): 87228

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 9.01656
system time used= 0.144009
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 44025
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= 1709
involuntary context switches= 1415

runsolver used 0 second user time and 0.008 second system time

The end