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/7c834c0e-51b8-11e0-a49e-00163e1e087d.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//7c834c0e-51b8-11e0-a49e-00163e1e087d.cudf /home/misc2010/tmp/201109011757/aspcud-1.5/7c834c0e-51b8-11e0-a49e-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.26 1.16 1.05 5/36 32136
/proc/meminfo: memFree=522164/1048576 swapFree=0/0
[pid=32134] ppid=32133 vsize=2592 CPUtime=0
/proc/32134/stat : 32134 (aspcud-1.5) S 32133 32134 22717 34817 22717 4202496 373 0 0 0 0 0 0 0 21 0 1 0 73034012 2654208 280 1283457024 134512640 135304128 4288840640 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/32134/statm: 648 280 234 194 0 35 0
[pid=32135] ppid=32134 vsize=2592 CPUtime=0
/proc/32135/stat : 32135 (aspcud-1.5) R 32134 32134 22717 34817 22717 4202560 110 0 0 0 0 0 0 0 25 0 1 0 73034012 2654208 133 1283457024 134512640 135304128 4288840640 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/32135/statm: 648 133 86 194 0 35 0
[pid=32136] ppid=32135 vsize=2592 CPUtime=0
/proc/32136/stat : 32136 (aspcud-1.5) R 32135 32134 22717 34817 22717 4202560 0 0 0 0 0 0 0 0 25 0 1 0 73034012 2654208 47 1283457024 134512640 135304128 4288840640 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/32136/statm: 648 47 0 194 0 35 0

[startup+0.151539 s]
/proc/loadavg: 1.26 1.16 1.05 5/36 32136
/proc/meminfo: memFree=522164/1048576 swapFree=0/0
[pid=32134] ppid=32133 vsize=2600 CPUtime=0
/proc/32134/stat : 32134 (aspcud-1.5) S 32133 32134 22717 34817 22717 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 73034012 2662400 299 1283457024 134512640 135304128 4288840640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32134/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.207619 s]
/proc/loadavg: 1.26 1.16 1.05 5/36 32136
/proc/meminfo: memFree=522164/1048576 swapFree=0/0
[pid=32134] ppid=32133 vsize=2600 CPUtime=0
/proc/32134/stat : 32134 (aspcud-1.5) S 32133 32134 22717 34817 22717 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 73034012 2662400 299 1283457024 134512640 135304128 4288840640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32134/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.307647 s]
/proc/loadavg: 1.26 1.16 1.05 5/36 32136
/proc/meminfo: memFree=522164/1048576 swapFree=0/0
[pid=32134] ppid=32133 vsize=2600 CPUtime=0
/proc/32134/stat : 32134 (aspcud-1.5) S 32133 32134 22717 34817 22717 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 73034012 2662400 299 1283457024 134512640 135304128 4288840640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32134/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.707564 s]
/proc/loadavg: 1.26 1.16 1.05 5/36 32136
/proc/meminfo: memFree=522164/1048576 swapFree=0/0
[pid=32134] ppid=32133 vsize=2600 CPUtime=0
/proc/32134/stat : 32134 (aspcud-1.5) S 32133 32134 22717 34817 22717 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 73034012 2662400 299 1283457024 134512640 135304128 4288840640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32134/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+1.50854 s]
/proc/loadavg: 1.24 1.15 1.05 2/38 32145
/proc/meminfo: memFree=484048/1048576 swapFree=0/0
[pid=32134] ppid=32133 vsize=2600 CPUtime=0
/proc/32134/stat : 32134 (aspcud-1.5) S 32133 32134 22717 34817 22717 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 73034012 2662400 299 1283457024 134512640 135304128 4288840640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32134/statm: 650 299 251 194 0 37 0
[pid=32143] ppid=32134 vsize=1932 CPUtime=0
/proc/32143/stat : 32143 (clasp) S 32134 32134 22717 34817 22717 4202496 293 0 0 0 0 0 0 0 25 0 1 0 73034013 1978368 160 1283457024 134512640 136285277 4286698016 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/32143/statm: 483 160 144 433 0 48 0
[pid=32144] ppid=32134 vsize=2588 CPUtime=0
/proc/32144/stat : 32144 (gringo) S 32134 32134 22717 34817 22717 4202496 405 0 0 0 0 0 0 0 25 0 1 0 73034013 2650112 272 1283457024 134512640 136933539 4288867488 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/32144/statm: 647 272 242 592 0 52 0
[pid=32145] ppid=32134 vsize=32748 CPUtime=1.28
/proc/32145/stat : 32145 (cudf2lp) R 32134 32134 22717 34817 22717 4202496 10538 0 0 0 122 6 0 0 25 0 1 0 73034013 33533952 7985 1283457024 134512640 135786343 4286698064 18446744073709551615 135219428 0 0 6 0 0 0 0 17 0 0 0 0
/proc/32145/statm: 8187 7985 136 311 0 7874 0
Current children cumulated CPU time (s) 1.28
Current children cumulated vsize (KiB) 39868

[startup+3.10893 s]
/proc/loadavg: 1.24 1.15 1.05 3/37 32145
/proc/meminfo: memFree=477776/1048576 swapFree=0/0
[pid=32134] ppid=32133 vsize=2600 CPUtime=2.11
/proc/32134/stat : 32134 (aspcud-1.5) S 32133 32134 22717 34817 22717 4202496 580 19483 0 0 0 0 201 10 15 0 1 0 73034012 2662400 299 1283457024 134512640 135304128 4288840640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32134/statm: 650 299 251 194 0 37 0
[pid=32143] ppid=32134 vsize=20988 CPUtime=0.75
/proc/32143/stat : 32143 (clasp) R 32134 32134 22717 34817 22717 4202496 6045 0 0 0 73 2 0 0 18 0 1 0 73034013 21491712 5004 1283457024 134512640 136285277 4286698016 18446744073709551615 134956176 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32143/statm: 5247 5004 234 433 0 4812 0
Current children cumulated CPU time (s) 2.86
Current children cumulated vsize (KiB) 23588

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

[startup+3.20897 s]
/proc/loadavg: 1.24 1.15 1.05 3/37 32145
/proc/meminfo: memFree=477776/1048576 swapFree=0/0
[pid=32134] ppid=32133 vsize=2600 CPUtime=2.11
/proc/32134/stat : 32134 (aspcud-1.5) S 32133 32134 22717 34817 22717 4202496 580 19483 0 0 0 0 201 10 15 0 1 0 73034012 2662400 299 1283457024 134512640 135304128 4288840640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32134/statm: 650 299 251 194 0 37 0
[pid=32143] ppid=32134 vsize=20988 CPUtime=0.85
/proc/32143/stat : 32143 (clasp) R 32134 32134 22717 34817 22717 4202496 6045 0 0 0 83 2 0 0 18 0 1 0 73034013 21491712 5004 1283457024 134512640 136285277 4286698016 18446744073709551615 134669408 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32143/statm: 5247 5004 234 433 0 4812 0
Current children cumulated CPU time (s) 2.96
Current children cumulated vsize (KiB) 23588

[startup+4.00924 s]
/proc/loadavg: 1.24 1.15 1.05 2/36 32145
/proc/meminfo: memFree=485480/1048576 swapFree=0/0
[pid=32134] ppid=32133 vsize=2600 CPUtime=2.11
/proc/32134/stat : 32134 (aspcud-1.5) S 32133 32134 22717 34817 22717 4202496 580 19483 0 0 0 0 201 10 15 0 1 0 73034012 2662400 299 1283457024 134512640 135304128 4288840640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32134/statm: 650 299 251 194 0 37 0
[pid=32143] ppid=32134 vsize=20988 CPUtime=1.65
/proc/32143/stat : 32143 (clasp) R 32134 32134 22717 34817 22717 4202496 6045 0 0 0 163 2 0 0 20 0 1 0 73034013 21491712 5004 1283457024 134512640 136285277 4286698016 18446744073709551615 134686305 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32143/statm: 5247 5004 234 433 0 4812 0
Current children cumulated CPU time (s) 3.76
Current children cumulated vsize (KiB) 23588

[startup+4.40934 s]
/proc/loadavg: 1.24 1.15 1.05 2/36 32145
/proc/meminfo: memFree=483992/1048576 swapFree=0/0
[pid=32134] ppid=32133 vsize=2600 CPUtime=2.11
/proc/32134/stat : 32134 (aspcud-1.5) S 32133 32134 22717 34817 22717 4202496 580 19483 0 0 0 0 201 10 15 0 1 0 73034012 2662400 299 1283457024 134512640 135304128 4288840640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32134/statm: 650 299 251 194 0 37 0
[pid=32143] ppid=32134 vsize=22848 CPUtime=2.05
/proc/32143/stat : 32143 (clasp) R 32134 32134 22717 34817 22717 4202496 6529 0 0 0 203 2 0 0 20 0 1 0 73034013 23396352 5488 1283457024 134512640 136285277 4286698016 18446744073709551615 134959924 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32143/statm: 5712 5488 234 433 0 5277 0
Current children cumulated CPU time (s) 4.16
Current children cumulated vsize (KiB) 25448

[startup+4.60939 s]
/proc/loadavg: 1.24 1.15 1.05 2/36 32145
/proc/meminfo: memFree=483992/1048576 swapFree=0/0
[pid=32134] ppid=32133 vsize=2600 CPUtime=2.11
/proc/32134/stat : 32134 (aspcud-1.5) S 32133 32134 22717 34817 22717 4202496 580 19483 0 0 0 0 201 10 15 0 1 0 73034012 2662400 299 1283457024 134512640 135304128 4288840640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32134/statm: 650 299 251 194 0 37 0
[pid=32143] ppid=32134 vsize=23112 CPUtime=2.25
/proc/32143/stat : 32143 (clasp) R 32134 32134 22717 34817 22717 4202496 6586 0 0 0 223 2 0 0 21 0 1 0 73034013 23666688 5545 1283457024 134512640 136285277 4286698016 18446744073709551615 134960023 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/32143/statm: 5778 5545 234 433 0 5343 0
Current children cumulated CPU time (s) 4.36
Current children cumulated vsize (KiB) 25712

Child status: 0
Real time (s): 4.6622
CPU time (s): 4.44028
CPU user time (s): 4.28827
CPU system time (s): 0.152009
CPU usage (%): 95.2399
Max. virtual memory (cumulated for all children) (KiB): 51228

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.28827
system time used= 0.152009
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 30301
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= 814
involuntary context switches= 667

runsolver used 0.012 second user time and 0 second system time

The end