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/201012061533/aspcud-paranoid-1.3/rand835640.cudf.impossible.log.runsolver ./aspcud-paranoid-1.3 /home/misc2010/data/2010/impossible//rand835640.cudf /home/misc2010/tmp/201012061533/aspcud-paranoid-1.3/rand835640.cudf.impossible.result 

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.38 1.26 1.19 2/45 23753
/proc/meminfo: memFree=901852/1048576 swapFree=2078744/2097144
[pid=23753] ppid=23752 vsize=3024 CPUtime=0
/proc/23753/stat : 23753 (runsolver) D 23752 23753 2059 34821 2220 4202560 73 0 0 0 0 0 0 0 25 0 1 0 876136242 3096576 94 1283457024 134512640 134586868 4294490336 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/23753/statm: 756 94 62 19 0 54 0

[startup+0.150451 s]
/proc/loadavg: 1.38 1.26 1.19 2/45 23753
/proc/meminfo: memFree=901852/1048576 swapFree=2078744/2097144
[pid=23753] ppid=23752 vsize=2600 CPUtime=0
/proc/23753/stat : 23753 (aspcud-paranoid) S 23752 23753 2059 34821 2220 4202496 664 2927 0 3 0 0 0 0 25 0 1 0 876136242 2662400 301 1283457024 134512640 135304128 4287582992 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23753/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.206453 s]
/proc/loadavg: 1.38 1.26 1.19 2/45 23753
/proc/meminfo: memFree=901852/1048576 swapFree=2078744/2097144
[pid=23753] ppid=23752 vsize=2600 CPUtime=0
/proc/23753/stat : 23753 (aspcud-paranoid) S 23752 23753 2059 34821 2220 4202496 664 2927 0 3 0 0 0 0 25 0 1 0 876136242 2662400 301 1283457024 134512640 135304128 4287582992 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23753/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.31143 s]
/proc/loadavg: 1.38 1.26 1.19 2/45 23753
/proc/meminfo: memFree=901852/1048576 swapFree=2078744/2097144
[pid=23753] ppid=23752 vsize=2600 CPUtime=0
/proc/23753/stat : 23753 (aspcud-paranoid) S 23752 23753 2059 34821 2220 4202496 664 2927 0 3 0 0 0 0 25 0 1 0 876136242 2662400 301 1283457024 134512640 135304128 4287582992 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23753/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.711519 s]
/proc/loadavg: 1.38 1.26 1.19 2/45 23753
/proc/meminfo: memFree=901852/1048576 swapFree=2078744/2097144
[pid=23753] ppid=23752 vsize=2600 CPUtime=0
/proc/23753/stat : 23753 (aspcud-paranoid) S 23752 23753 2059 34821 2220 4202496 664 2927 0 3 0 0 0 0 25 0 1 0 876136242 2662400 301 1283457024 134512640 135304128 4287582992 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23753/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+1.51169 s]
/proc/loadavg: 1.51 1.29 1.20 2/49 23770
/proc/meminfo: memFree=863540/1048576 swapFree=2078744/2097144
[pid=23753] ppid=23752 vsize=2600 CPUtime=0
/proc/23753/stat : 23753 (aspcud-paranoid) S 23752 23753 2059 34821 2220 4202496 664 2927 0 3 0 0 0 0 25 0 1 0 876136242 2662400 301 1283457024 134512640 135304128 4287582992 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23753/statm: 650 301 253 194 0 36 0
[pid=23768] ppid=23753 vsize=1864 CPUtime=0
/proc/23768/stat : 23768 (clasp) S 23753 23753 2059 34821 2220 4202496 270 0 15 0 0 0 0 0 24 0 1 0 876136248 1908736 152 1283457024 134512640 136223643 4288920608 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/23768/statm: 466 152 138 418 0 46 0
[pid=23769] ppid=23753 vsize=2608 CPUtime=0
/proc/23769/stat : 23769 (gringo) S 23753 23753 2059 34821 2220 4202496 385 0 23 0 0 0 0 0 24 0 1 0 876136248 2670592 277 1283457024 134512640 136959103 4287285696 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/23769/statm: 652 277 247 598 0 51 0
[pid=23770] ppid=23753 vsize=52456 CPUtime=1.3
/proc/23770/stat : 23770 (cudf2lp) R 23753 23753 2059 34821 2220 4202496 14460 0 14 0 127 3 0 0 25 0 1 0 876136248 53714944 12319 1283457024 134512640 135749571 4288916832 18446744073709551615 134543474 0 0 6 0 0 0 0 17 0 0 0 0
/proc/23770/statm: 13114 12319 127 302 0 12810 0
Current children cumulated CPU time (s) 1.3
Current children cumulated vsize (KiB) 59528

[startup+3.11204 s]
/proc/loadavg: 1.51 1.29 1.20 4/49 23770
/proc/meminfo: memFree=826780/1048576 swapFree=2078744/2097144
[pid=23753] ppid=23752 vsize=2600 CPUtime=2.06
/proc/23753/stat : 23753 (aspcud-paranoid) S 23752 23753 2059 34821 2220 4202496 665 21919 0 18 0 0 200 6 18 0 1 0 876136242 2662400 301 1283457024 134512640 135304128 4287582992 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23753/statm: 650 301 253 194 0 36 0
[pid=23768] ppid=23753 vsize=18592 CPUtime=0.04
/proc/23768/stat : 23768 (clasp) R 23753 23753 2059 34821 2220 4202496 5096 0 18 0 4 0 0 0 18 0 1 0 876136248 19038208 4323 1283457024 134512640 136223643 4288920608 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23768/statm: 4648 4323 174 418 0 4228 0
[pid=23769] ppid=23753 vsize=29084 CPUtime=0.79
/proc/23769/stat : 23769 (gringo) R 23753 23753 2059 34821 2220 4202496 8235 0 23 0 76 3 0 0 18 0 1 0 876136248 29782016 6083 1283457024 134512640 136959103 4287285696 18446744073709551615 134738012 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23769/statm: 7271 6083 256 598 0 6670 0
Current children cumulated CPU time (s) 2.89
Current children cumulated vsize (KiB) 50276

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

[startup+3.21207 s]
/proc/loadavg: 1.51 1.29 1.20 4/49 23770
/proc/meminfo: memFree=826780/1048576 swapFree=2078744/2097144
[pid=23753] ppid=23752 vsize=2600 CPUtime=2.06
/proc/23753/stat : 23753 (aspcud-paranoid) S 23752 23753 2059 34821 2220 4202496 665 21919 0 18 0 0 200 6 18 0 1 0 876136242 2662400 301 1283457024 134512640 135304128 4287582992 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23753/statm: 650 301 253 194 0 36 0
[pid=23768] ppid=23753 vsize=22208 CPUtime=0.05
/proc/23768/stat : 23768 (clasp) R 23753 23753 2059 34821 2220 4202496 5806 0 18 0 5 0 0 0 18 0 1 0 876136248 22740992 5033 1283457024 134512640 136223643 4288920608 18446744073709551615 135628159 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23768/statm: 5552 5033 174 418 0 5132 0
[pid=23769] ppid=23753 vsize=36688 CPUtime=0.87
/proc/23769/stat : 23769 (gringo) R 23753 23753 2059 34821 2220 4202496 10036 0 23 0 83 4 0 0 18 0 1 0 876136248 37568512 6859 1283457024 134512640 136959103 4287285696 18446744073709551615 135656494 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23769/statm: 9172 6859 256 598 0 8571 0
Current children cumulated CPU time (s) 2.98
Current children cumulated vsize (KiB) 61496

[startup+4.01282 s]
/proc/loadavg: 1.51 1.29 1.20 3/48 23770
/proc/meminfo: memFree=847008/1048576 swapFree=2078744/2097144
[pid=23753] ppid=23752 vsize=2600 CPUtime=3.37
/proc/23753/stat : 23753 (aspcud-paranoid) S 23752 23753 2059 34821 2220 4202496 665 34484 0 41 0 0 324 13 18 0 1 0 876136242 2662400 301 1283457024 134512640 135304128 4287582992 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23753/statm: 650 301 253 194 0 36 0
[pid=23768] ppid=23753 vsize=37124 CPUtime=0.42
/proc/23768/stat : 23768 (clasp) R 23753 23753 2059 34821 2220 4202496 10360 0 19 0 40 2 0 0 18 0 1 0 876136248 38014976 8502 1283457024 134512640 136223643 4288920608 18446744073709551615 134867486 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23768/statm: 9281 8502 214 418 0 8861 0
Current children cumulated CPU time (s) 3.79
Current children cumulated vsize (KiB) 39724

[startup+4.41293 s]
/proc/loadavg: 1.51 1.29 1.20 2/47 23770
/proc/meminfo: memFree=863396/1048576 swapFree=2078744/2097144
[pid=23753] ppid=23752 vsize=2600 CPUtime=3.37
/proc/23753/stat : 23753 (aspcud-paranoid) S 23752 23753 2059 34821 2220 4202496 665 34484 0 41 0 0 324 13 18 0 1 0 876136242 2662400 301 1283457024 134512640 135304128 4287582992 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23753/statm: 650 301 253 194 0 36 0
[pid=23768] ppid=23753 vsize=36580 CPUtime=0.82
/proc/23768/stat : 23768 (clasp) R 23753 23753 2059 34821 2220 4202496 10380 0 19 0 80 2 0 0 18 0 1 0 876136248 37457920 8390 1283457024 134512640 136223643 4288920608 18446744073709551615 134870708 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23768/statm: 9145 8390 223 418 0 8725 0
Current children cumulated CPU time (s) 4.19
Current children cumulated vsize (KiB) 39180

[startup+4.61366 s]
/proc/loadavg: 1.51 1.29 1.20 2/47 23770
/proc/meminfo: memFree=863396/1048576 swapFree=2078744/2097144
[pid=23753] ppid=23752 vsize=2600 CPUtime=3.37
/proc/23753/stat : 23753 (aspcud-paranoid) S 23752 23753 2059 34821 2220 4202496 665 34484 0 41 0 0 324 13 18 0 1 0 876136242 2662400 301 1283457024 134512640 135304128 4287582992 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23753/statm: 650 301 253 194 0 36 0
[pid=23768] ppid=23753 vsize=36580 CPUtime=1.02
/proc/23768/stat : 23768 (clasp) R 23753 23753 2059 34821 2220 4202496 10387 0 19 0 100 2 0 0 19 0 1 0 876136248 37457920 7373 1283457024 134512640 136223643 4288920608 18446744073709551615 135671233 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23768/statm: 9145 7373 230 418 0 8725 0
Current children cumulated CPU time (s) 4.39
Current children cumulated vsize (KiB) 39180

Child status: 0
Real time (s): 4.66271
CPU time (s): 4.42028
CPU user time (s): 4.25627
CPU system time (s): 0.16401
CPU usage (%): 94.8006
Max. virtual memory (cumulated for all children) (KiB): 93732

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.25627
system time used= 0.16401
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 49103
page faults= 62
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1637
involuntary context switches= 1120

runsolver used 0 second user time and 0 second system time

The end