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/201108311143/aspcud-1.5/d023d256-3477-11e0-bdb2-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//d023d256-3477-11e0-bdb2-00163e3d3b7c.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/d023d256-3477-11e0-bdb2-00163e3d3b7c.cudf.dudf-real.result -sum(installedsize) 

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.20 1.06 1.01 3/34 1578
/proc/meminfo: memFree=323496/1048576 swapFree=0/0
[pid=1577] ppid=1576 vsize=2588 CPUtime=0
/proc/1577/stat : 1577 (aspcud-1.5) R 1576 1577 19908 34817 19908 4202496 365 0 0 0 0 0 0 0 25 0 1 0 67724206 2650112 279 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/1577/statm: 647 279 234 194 0 34 0
[pid=1578] ppid=1577 vsize=2588 CPUtime=0
/proc/1578/stat : 1578 (aspcud-1.5) R 1577 1577 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 67724206 2650112 45 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/1578/statm: 647 45 0 194 0 34 0

[startup+0.176486 s]
/proc/loadavg: 1.20 1.06 1.01 3/34 1578
/proc/meminfo: memFree=323496/1048576 swapFree=0/0
[pid=1577] ppid=1576 vsize=2596 CPUtime=0.01
/proc/1577/stat : 1577 (aspcud-1.5) S 1576 1577 19908 34817 19908 4202496 580 1519 0 0 0 0 0 1 25 0 1 0 67724206 2658304 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1577/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.206101 s]
/proc/loadavg: 1.20 1.06 1.01 3/34 1578
/proc/meminfo: memFree=323496/1048576 swapFree=0/0
[pid=1577] ppid=1576 vsize=2596 CPUtime=0.01
/proc/1577/stat : 1577 (aspcud-1.5) S 1576 1577 19908 34817 19908 4202496 580 1519 0 0 0 0 0 1 25 0 1 0 67724206 2658304 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1577/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.304515 s]
/proc/loadavg: 1.20 1.06 1.01 3/34 1578
/proc/meminfo: memFree=323496/1048576 swapFree=0/0
[pid=1577] ppid=1576 vsize=2596 CPUtime=0.01
/proc/1577/stat : 1577 (aspcud-1.5) S 1576 1577 19908 34817 19908 4202496 580 1519 0 0 0 0 0 1 25 0 1 0 67724206 2658304 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1577/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.707309 s]
/proc/loadavg: 1.20 1.06 1.01 3/34 1578
/proc/meminfo: memFree=323496/1048576 swapFree=0/0
[pid=1577] ppid=1576 vsize=2596 CPUtime=0.01
/proc/1577/stat : 1577 (aspcud-1.5) S 1576 1577 19908 34817 19908 4202496 580 1519 0 0 0 0 0 1 25 0 1 0 67724206 2658304 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1577/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+1.5116 s]
/proc/loadavg: 1.19 1.06 1.01 2/37 1588
/proc/meminfo: memFree=287576/1048576 swapFree=0/0
[pid=1577] ppid=1576 vsize=2596 CPUtime=0.01
/proc/1577/stat : 1577 (aspcud-1.5) S 1576 1577 19908 34817 19908 4202496 580 1519 0 0 0 0 0 1 25 0 1 0 67724206 2658304 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1577/statm: 649 298 251 194 0 36 0
[pid=1586] ppid=1577 vsize=3196 CPUtime=0
/proc/1586/stat : 1586 (clasp) S 1577 1577 19908 34817 19908 4202496 656 0 0 0 0 0 0 0 18 0 1 0 67724207 3272704 523 1283457024 134512640 136285277 4293746896 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/1586/statm: 799 523 176 433 0 364 0
[pid=1587] ppid=1577 vsize=4468 CPUtime=0.08
/proc/1587/stat : 1587 (gringo) R 1577 1577 19908 34817 19908 4202496 924 0 0 0 8 0 0 0 18 0 1 0 67724207 4575232 693 1283457024 134512640 136933539 4286735008 18446744073709551615 136180200 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/1587/statm: 1117 693 242 592 0 522 0
[pid=1588] ppid=1577 vsize=29224 CPUtime=1.06
/proc/1588/stat : 1588 (cudf2lp) R 1577 1577 19908 34817 19908 4202496 9417 0 0 0 98 8 0 0 25 0 1 0 67724207 29925376 7085 1283457024 134512640 135786343 4290791056 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/1588/statm: 7306 7085 139 311 0 6993 0
Current children cumulated CPU time (s) 1.15
Current children cumulated vsize (KiB) 39484

[startup+3.10209 s]
/proc/loadavg: 1.19 1.06 1.01 2/35 1588
/proc/meminfo: memFree=296952/1048576 swapFree=0/0
[pid=1577] ppid=1576 vsize=2596 CPUtime=1.65
/proc/1577/stat : 1577 (aspcud-1.5) S 1576 1577 19908 34817 19908 4202496 580 15662 0 0 0 0 151 14 17 0 1 0 67724206 2658304 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1577/statm: 649 298 251 194 0 36 0
[pid=1586] ppid=1577 vsize=13060 CPUtime=1.09
/proc/1586/stat : 1586 (clasp) R 1577 1577 19908 34817 19908 4202496 3699 0 0 0 109 0 0 0 19 0 1 0 67724207 13373440 3054 1283457024 134512640 136285277 4293746896 18446744073709551615 134955202 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1586/statm: 3265 3054 234 433 0 2830 0
Current children cumulated CPU time (s) 2.74
Current children cumulated vsize (KiB) 15656

[startup+6.30282 s]
/proc/loadavg: 1.17 1.06 1.01 2/35 1588
/proc/meminfo: memFree=295464/1048576 swapFree=0/0
[pid=1577] ppid=1576 vsize=2596 CPUtime=1.65
/proc/1577/stat : 1577 (aspcud-1.5) S 1576 1577 19908 34817 19908 4202496 580 15662 0 0 0 0 151 14 17 0 1 0 67724206 2658304 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1577/statm: 649 298 251 194 0 36 0
[pid=1586] ppid=1577 vsize=15172 CPUtime=4.29
/proc/1586/stat : 1586 (clasp) R 1577 1577 19908 34817 19908 4202496 4202 0 0 0 429 0 0 0 25 0 1 0 67724207 15536128 3557 1283457024 134512640 136285277 4293746896 18446744073709551615 134966730 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1586/statm: 3793 3557 234 433 0 3358 0
Current children cumulated CPU time (s) 5.94
Current children cumulated vsize (KiB) 17768

[startup+12.7142 s]
/proc/loadavg: 1.16 1.06 1.01 2/35 1588
/proc/meminfo: memFree=295472/1048576 swapFree=0/0
[pid=1577] ppid=1576 vsize=2596 CPUtime=1.65
/proc/1577/stat : 1577 (aspcud-1.5) S 1576 1577 19908 34817 19908 4202496 580 15662 0 0 0 0 151 14 17 0 1 0 67724206 2658304 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1577/statm: 649 298 251 194 0 36 0
[pid=1586] ppid=1577 vsize=15172 CPUtime=10.7
/proc/1586/stat : 1586 (clasp) R 1577 1577 19908 34817 19908 4202496 4202 0 0 0 1070 0 0 0 25 0 1 0 67724207 15536128 3557 1283457024 134512640 136285277 4293746896 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1586/statm: 3793 3557 234 433 0 3358 0
Current children cumulated CPU time (s) 12.35
Current children cumulated vsize (KiB) 17768

[startup+25.507 s]
/proc/loadavg: 1.12 1.05 1.01 2/35 1588
/proc/meminfo: memFree=294728/1048576 swapFree=0/0
[pid=1577] ppid=1576 vsize=2596 CPUtime=1.65
/proc/1577/stat : 1577 (aspcud-1.5) S 1576 1577 19908 34817 19908 4202496 580 15662 0 0 0 0 151 14 17 0 1 0 67724206 2658304 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1577/statm: 649 298 251 194 0 36 0
[pid=1586] ppid=1577 vsize=15832 CPUtime=23.49
/proc/1586/stat : 1586 (clasp) R 1577 1577 19908 34817 19908 4202496 4386 0 0 0 2347 2 0 0 25 0 1 0 67724207 16211968 3741 1283457024 134512640 136285277 4293746896 18446744073709551615 134966952 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1586/statm: 3958 3741 234 433 0 3523 0
Current children cumulated CPU time (s) 25.14
Current children cumulated vsize (KiB) 18428

[startup+51.1126 s]
/proc/loadavg: 1.08 1.05 1.01 2/37 1591
/proc/meminfo: memFree=293464/1048576 swapFree=0/0
[pid=1577] ppid=1576 vsize=2596 CPUtime=1.65
/proc/1577/stat : 1577 (aspcud-1.5) S 1576 1577 19908 34817 19908 4202496 580 15662 0 0 0 0 151 14 17 0 1 0 67724206 2658304 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1577/statm: 649 298 251 194 0 36 0
[pid=1586] ppid=1577 vsize=16888 CPUtime=49.09
/proc/1586/stat : 1586 (clasp) R 1577 1577 19908 34817 19908 4202496 4654 0 0 0 4907 2 0 0 25 0 1 0 67724207 17293312 4009 1283457024 134512640 136285277 4293746896 18446744073709551615 134955659 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1586/statm: 4222 4009 234 433 0 3787 0
Current children cumulated CPU time (s) 50.74
Current children cumulated vsize (KiB) 19484

[startup+102.314 s]
/proc/loadavg: 1.03 1.04 1.00 2/37 1596
/proc/meminfo: memFree=291976/1048576 swapFree=0/0
[pid=1577] ppid=1576 vsize=2596 CPUtime=1.65
/proc/1577/stat : 1577 (aspcud-1.5) S 1576 1577 19908 34817 19908 4202496 580 15662 0 0 0 0 151 14 17 0 1 0 67724206 2658304 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1577/statm: 649 298 251 194 0 36 0
[pid=1586] ppid=1577 vsize=18360 CPUtime=100.26
/proc/1586/stat : 1586 (clasp) R 1577 1577 19908 34817 19908 4202496 4999 0 0 0 10023 3 0 0 25 0 1 0 67724207 18800640 4354 1283457024 134512640 136285277 4293746896 18446744073709551615 134615179 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1586/statm: 4590 4354 234 433 0 4155 0
Current children cumulated CPU time (s) 101.91
Current children cumulated vsize (KiB) 20956

[startup+162.308 s]
/proc/loadavg: 1.01 1.03 1.00 2/36 1599
/proc/meminfo: memFree=290504/1048576 swapFree=0/0
[pid=1577] ppid=1576 vsize=2596 CPUtime=1.65
/proc/1577/stat : 1577 (aspcud-1.5) S 1576 1577 19908 34817 19908 4202496 580 15662 0 0 0 0 151 14 17 0 1 0 67724206 2658304 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1577/statm: 649 298 251 194 0 36 0
[pid=1586] ppid=1577 vsize=19680 CPUtime=160.2
/proc/1586/stat : 1586 (clasp) R 1577 1577 19908 34817 19908 4202496 5342 0 0 0 16017 3 0 0 25 0 1 0 67724207 20152320 4697 1283457024 134512640 136285277 4293746896 18446744073709551615 134733794 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1586/statm: 4920 4697 234 433 0 4485 0
Current children cumulated CPU time (s) 161.85
Current children cumulated vsize (KiB) 22276

[startup+222.31 s]
/proc/loadavg: 1.00 1.02 1.00 2/35 1599
/proc/meminfo: memFree=290140/1048576 swapFree=0/0
[pid=1577] ppid=1576 vsize=2596 CPUtime=1.65
/proc/1577/stat : 1577 (aspcud-1.5) S 1576 1577 19908 34817 19908 4202496 580 15662 0 0 0 0 151 14 17 0 1 0 67724206 2658304 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1577/statm: 649 298 251 194 0 36 0
[pid=1586] ppid=1577 vsize=20208 CPUtime=220.17
/proc/1586/stat : 1586 (clasp) R 1577 1577 19908 34817 19908 4202496 5488 0 0 0 22014 3 0 0 25 0 1 0 67724207 20692992 4843 1283457024 134512640 136285277 4293746896 18446744073709551615 134959552 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1586/statm: 5052 4843 234 433 0 4617 0
Current children cumulated CPU time (s) 221.82
Current children cumulated vsize (KiB) 22804

[startup+282.304 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 1603
/proc/meminfo: memFree=288896/1048576 swapFree=0/0
[pid=1577] ppid=1576 vsize=2596 CPUtime=1.65
/proc/1577/stat : 1577 (aspcud-1.5) S 1576 1577 19908 34817 19908 4202496 580 15662 0 0 0 0 151 14 17 0 1 0 67724206 2658304 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1577/statm: 649 298 251 194 0 36 0
[pid=1586] ppid=1577 vsize=21304 CPUtime=280.1
/proc/1586/stat : 1586 (clasp) R 1577 1577 19908 34817 19908 4202496 5998 0 0 0 28007 3 0 0 25 0 1 0 67724207 21815296 5091 1283457024 134512640 136285277 4293746896 18446744073709551615 134966793 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1586/statm: 5326 5091 234 433 0 4891 0
Current children cumulated CPU time (s) 281.75
Current children cumulated vsize (KiB) 23900



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.608 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 1603
/proc/meminfo: memFree=286292/1048576 swapFree=0/0
[pid=1577] ppid=1576 vsize=2596 CPUtime=1.65
/proc/1577/stat : 1577 (aspcud-1.5) S 1576 1577 19908 34817 19908 4202496 580 15662 0 0 0 0 151 14 17 0 1 0 67724206 2658304 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1577/statm: 649 298 251 194 0 36 0
[pid=1586] ppid=1577 vsize=23816 CPUtime=288.44
/proc/1586/stat : 1586 (clasp) R 1577 1577 19908 34817 19908 4202496 6644 0 0 0 28841 3 0 0 25 0 1 0 67724207 24387584 5737 1283457024 134512640 136285277 4293746896 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1586/statm: 5954 5737 234 433 0 5519 0
Current children cumulated CPU time (s) 290.09
Current children cumulated vsize (KiB) 26412

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

Child status: 0
Real time (s): 290.636
CPU time (s): 290.122
CPU user time (s): 289.942
CPU system time (s): 0.180011
CPU usage (%): 99.8231
Max. virtual memory (cumulated for all children) (KiB): 43472

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.942
system time used= 0.180011
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 26669
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= 576
involuntary context switches= 3962

runsolver used 0 second user time and 0 second system time

The end