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/201108251442/aspcud-paranoid-1.5/rand399.cudf.s-e-l.log.runsolver ./aspcud-paranoid-1.5 /home/misc2010/data/2011/incremental/s-e-l/rand399.cudf /home/misc2010/tmp/201108251442/aspcud-paranoid-1.5/rand399.cudf.s-e-l.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: 0.97 1.01 1.00 5/38 11321
/proc/meminfo: memFree=370988/1048576 swapFree=0/0
[pid=11318] ppid=11317 vsize=2584 CPUtime=0
/proc/11318/stat : 11318 (aspcud-paranoid) S 11317 11318 4778 34817 4778 4202496 373 0 0 0 0 0 0 0 18 0 1 0 10563141 2646016 279 1283457024 134512640 135304128 4292075360 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/11318/statm: 646 279 234 194 0 33 0
[pid=11319] ppid=11318 vsize=2584 CPUtime=0
/proc/11319/stat : 11319 (aspcud-paranoid) S 11318 11318 4778 34817 4778 4202560 118 0 0 0 0 0 0 0 18 0 1 0 10563141 2646016 133 1283457024 134512640 135304128 4292075360 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/11319/statm: 646 133 87 194 0 33 0
[pid=11320] ppid=11319 vsize=2584 CPUtime=0
/proc/11320/stat : 11320 (aspcud-paranoid) R 11319 11318 4778 34817 4778 4202560 127 0 0 0 0 0 0 0 25 0 1 0 10563141 2646016 150 1283457024 134512640 135304128 4292075360 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/11320/statm: 646 150 104 194 0 33 0
[pid=11321] ppid=11320 vsize=2584 CPUtime=0
/proc/11321/stat : 11321 (aspcud-paranoid) R 11320 11318 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 10563141 2646016 46 1283457024 134512640 135304128 4292075360 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/11321/statm: 646 46 0 194 0 33 0

[startup+0.157033 s]
/proc/loadavg: 0.97 1.01 1.00 5/38 11321
/proc/meminfo: memFree=370988/1048576 swapFree=0/0
[pid=11318] ppid=11317 vsize=2592 CPUtime=0.02
/proc/11318/stat : 11318 (aspcud-paranoid) S 11317 11318 4778 34817 4778 4202496 648 2939 0 0 0 0 0 2 25 0 1 0 10563141 2654208 298 1283457024 134512640 135304128 4292075360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11318/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2592

[startup+0.20504 s]
/proc/loadavg: 0.97 1.01 1.00 5/38 11321
/proc/meminfo: memFree=370988/1048576 swapFree=0/0
[pid=11318] ppid=11317 vsize=2592 CPUtime=0.02
/proc/11318/stat : 11318 (aspcud-paranoid) S 11317 11318 4778 34817 4778 4202496 648 2939 0 0 0 0 0 2 25 0 1 0 10563141 2654208 298 1283457024 134512640 135304128 4292075360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11318/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2592

[startup+0.305031 s]
/proc/loadavg: 0.97 1.01 1.00 5/38 11321
/proc/meminfo: memFree=370988/1048576 swapFree=0/0
[pid=11318] ppid=11317 vsize=2592 CPUtime=0.02
/proc/11318/stat : 11318 (aspcud-paranoid) S 11317 11318 4778 34817 4778 4202496 648 2939 0 0 0 0 0 2 25 0 1 0 10563141 2654208 298 1283457024 134512640 135304128 4292075360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11318/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2592

[startup+0.712438 s]
/proc/loadavg: 0.97 1.01 1.00 5/38 11321
/proc/meminfo: memFree=370988/1048576 swapFree=0/0
[pid=11318] ppid=11317 vsize=2592 CPUtime=0.02
/proc/11318/stat : 11318 (aspcud-paranoid) S 11317 11318 4778 34817 4778 4202496 648 2939 0 0 0 0 0 2 25 0 1 0 10563141 2654208 298 1283457024 134512640 135304128 4292075360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11318/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2592

[startup+1.51277 s]
/proc/loadavg: 1.05 1.03 1.00 2/39 11335
/proc/meminfo: memFree=329828/1048576 swapFree=0/0
[pid=11318] ppid=11317 vsize=2592 CPUtime=0.02
/proc/11318/stat : 11318 (aspcud-paranoid) S 11317 11318 4778 34817 4778 4202496 648 2939 0 0 0 0 0 2 25 0 1 0 10563141 2654208 298 1283457024 134512640 135304128 4292075360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11318/statm: 648 298 251 194 0 35 0
[pid=11333] ppid=11318 vsize=5840 CPUtime=0.02
/proc/11333/stat : 11333 (clasp) R 11318 11318 4778 34817 4778 4202496 1352 0 0 0 2 0 0 0 18 0 1 0 10563143 5980160 1138 1283457024 134512640 136285277 4290715088 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/11333/statm: 1460 1138 177 433 0 1025 0
[pid=11334] ppid=11318 vsize=7400 CPUtime=0.2
/proc/11334/stat : 11334 (gringo) R 11318 11318 4778 34817 4778 4202496 1923 0 0 0 20 0 0 0 18 0 1 0 10563143 7577600 1369 1283457024 134512640 136933539 4288857232 18446744073709551615 134794734 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11334/statm: 1850 1369 242 592 0 1255 0
[pid=11335] ppid=11318 vsize=30572 CPUtime=1.1
/proc/11335/stat : 11335 (cudf2lp) R 11318 11318 4778 34817 4778 4202496 10055 0 0 0 106 4 0 0 25 0 1 0 10563143 31305728 7426 1283457024 134512640 135786343 4289774976 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/11335/statm: 7643 7426 137 311 0 7330 0
Current children cumulated CPU time (s) 1.34
Current children cumulated vsize (KiB) 46404

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

[startup+1.60279 s]
/proc/loadavg: 1.05 1.03 1.00 2/39 11335
/proc/meminfo: memFree=329828/1048576 swapFree=0/0
[pid=11318] ppid=11317 vsize=2592 CPUtime=0.02
/proc/11318/stat : 11318 (aspcud-paranoid) S 11317 11318 4778 34817 4778 4202496 648 2939 0 0 0 0 0 2 25 0 1 0 10563141 2654208 298 1283457024 134512640 135304128 4292075360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11318/statm: 648 298 251 194 0 35 0
[pid=11333] ppid=11318 vsize=7056 CPUtime=0.02
/proc/11333/stat : 11333 (clasp) R 11318 11318 4778 34817 4778 4202496 1686 0 0 0 2 0 0 0 18 0 1 0 10563143 7225344 1472 1283457024 134512640 136285277 4290715088 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/11333/statm: 1764 1472 177 433 0 1329 0
[pid=11334] ppid=11318 vsize=9940 CPUtime=0.27
/proc/11334/stat : 11334 (gringo) R 11318 11318 4778 34817 4778 4202496 2675 0 0 0 27 0 0 0 18 0 1 0 10563143 10178560 1767 1283457024 134512640 136933539 4288857232 18446744073709551615 134538971 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11334/statm: 2485 1767 242 592 0 1890 0
[pid=11335] ppid=11318 vsize=30572 CPUtime=1.12
/proc/11335/stat : 11335 (cudf2lp) R 11318 11318 4778 34817 4778 4202496 10055 0 0 0 108 4 0 0 25 0 1 0 10563143 31305728 7426 1283457024 134512640 135786343 4289774976 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/11335/statm: 7643 7426 137 311 0 7330 0
Current children cumulated CPU time (s) 1.43
Current children cumulated vsize (KiB) 50160

[startup+2.40303 s]
/proc/loadavg: 1.05 1.03 1.00 3/38 11335
/proc/meminfo: memFree=318560/1048576 swapFree=0/0
[pid=11318] ppid=11317 vsize=2592 CPUtime=2
/proc/11318/stat : 11318 (aspcud-paranoid) S 11317 11318 4778 34817 4778 4202496 648 20871 0 0 0 0 190 10 15 0 1 0 10563141 2654208 298 1283457024 134512640 135304128 4292075360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11318/statm: 648 298 251 194 0 35 0
[pid=11333] ppid=11318 vsize=23400 CPUtime=0.24
/proc/11333/stat : 11333 (clasp) R 11318 11318 4778 34817 4778 4202496 6651 0 0 0 22 2 0 0 18 0 1 0 10563143 23961600 5577 1283457024 134512640 136285277 4290715088 18446744073709551615 134901848 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/11333/statm: 5850 5577 217 433 0 5415 0
Current children cumulated CPU time (s) 2.24
Current children cumulated vsize (KiB) 25992

[startup+2.80387 s]
/proc/loadavg: 1.05 1.03 1.00 3/38 11335
/proc/meminfo: memFree=318560/1048576 swapFree=0/0
[pid=11318] ppid=11317 vsize=2592 CPUtime=2
/proc/11318/stat : 11318 (aspcud-paranoid) S 11317 11318 4778 34817 4778 4202496 648 20871 0 0 0 0 190 10 15 0 1 0 10563141 2654208 298 1283457024 134512640 135304128 4292075360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11318/statm: 648 298 251 194 0 35 0
[pid=11333] ppid=11318 vsize=16264 CPUtime=0.64
/proc/11333/stat : 11333 (clasp) R 11318 11318 4778 34817 4778 4202496 6676 0 0 0 60 4 0 0 18 0 1 0 10563143 16654336 1816 1283457024 134512640 136285277 4290715088 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/11333/statm: 4066 1816 242 433 0 3631 0
Current children cumulated CPU time (s) 2.64
Current children cumulated vsize (KiB) 18856

Child status: 0
Real time (s): 2.82528
CPU time (s): 2.66817
CPU user time (s): 2.50416
CPU system time (s): 0.16401
CPU usage (%): 94.439
Max. virtual memory (cumulated for all children) (KiB): 50868

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 2.50416
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= 31811
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= 836
involuntary context switches= 634

runsolver used 0 second user time and 0 second system time

The end