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: runsolver -s SIGUSR1 -M 1124 -C 300 -d 10 -w /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/dist-upgrade/upgrade/difficult/rand491.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/upgrade/difficult/rand491.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/dist-upgrade/upgrade/difficult/rand491.cudf.result -notuptodate(solution),-aligned(solution,source,sourceversion),-unsat_recommends(solution),-count(new) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 300 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 330 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

[startup+0 s]
/proc/loadavg: 1.03 1.03 1.00 2/59 13695
/proc/meminfo: memFree=506704/1022884 swapFree=0/0
[pid=13695] ppid=13694 vsize=3152 CPUtime=0
/proc/13695/stat : 13695 (runsolver) R 13694 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 118037276 3227648 33 18446744073709551615 134512640 134586868 4288714976 4288713024 4151465008 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/13695/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.127152 s]
/proc/loadavg: 1.03 1.03 1.00 2/59 13695
/proc/meminfo: memFree=506704/1022884 swapFree=0/0
[pid=13695] ppid=13694 vsize=9212 CPUtime=0.03
/proc/13695/stat : 13695 (aspuncud-full) S 13694 13695 1750 0 -1 4202496 693 2807 2 7 0 0 2 1 20 0 1 0 118037276 9433088 364 18446744073709551615 4194304 5129932 140736324905984 140736324904640 139778502558814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13695/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200328 s]
/proc/loadavg: 1.03 1.03 1.00 2/59 13695
/proc/meminfo: memFree=506704/1022884 swapFree=0/0
[pid=13695] ppid=13694 vsize=9212 CPUtime=0.03
/proc/13695/stat : 13695 (aspuncud-full) S 13694 13695 1750 0 -1 4202496 693 2807 2 7 0 0 2 1 20 0 1 0 118037276 9433088 364 18446744073709551615 4194304 5129932 140736324905984 140736324904640 139778502558814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13695/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300331 s]
/proc/loadavg: 1.03 1.03 1.00 2/59 13695
/proc/meminfo: memFree=506704/1022884 swapFree=0/0
[pid=13695] ppid=13694 vsize=9212 CPUtime=0.03
/proc/13695/stat : 13695 (aspuncud-full) S 13694 13695 1750 0 -1 4202496 693 2807 2 7 0 0 2 1 20 0 1 0 118037276 9433088 364 18446744073709551615 4194304 5129932 140736324905984 140736324904640 139778502558814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13695/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700218 s]
/proc/loadavg: 1.03 1.03 1.00 2/59 13695
/proc/meminfo: memFree=506704/1022884 swapFree=0/0
[pid=13695] ppid=13694 vsize=9212 CPUtime=0.03
/proc/13695/stat : 13695 (aspuncud-full) S 13694 13695 1750 0 -1 4202496 693 2807 2 7 0 0 2 1 20 0 1 0 118037276 9433088 364 18446744073709551615 4194304 5129932 140736324905984 140736324904640 139778502558814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13695/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 1.03 1.03 1.00 2/61 13708
/proc/meminfo: memFree=471712/1022884 swapFree=0/0
[pid=13695] ppid=13694 vsize=9212 CPUtime=0.03
/proc/13695/stat : 13695 (aspuncud-full) S 13694 13695 1750 0 -1 4202496 693 2807 2 7 0 0 2 1 20 0 1 0 118037276 9433088 364 18446744073709551615 4194304 5129932 140736324905984 140736324904640 139778502558814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13695/statm: 2303 364 303 229 0 63 0
[pid=13708] ppid=13695 vsize=31648 CPUtime=1.3
/proc/13708/stat : 13708 (cudf2lp) R 13695 13695 1750 0 -1 4202496 9278 0 1 0 124 6 0 0 20 0 1 0 118037287 32407552 7545 18446744073709551615 4194304 5690517 140734380278192 140734380274680 4357477 0 0 16781316 0 0 0 0 17 0 0 0 6 0 0
/proc/13708/statm: 7912 7545 159 366 0 7543 0
Current children cumulated CPU time (s) 1.33
Current children cumulated vsize (KiB) 40860

[startup+3.10026 s]
/proc/loadavg: 1.03 1.03 1.00 2/61 13708
/proc/meminfo: memFree=439472/1022884 swapFree=0/0
[pid=13695] ppid=13694 vsize=9212 CPUtime=0.03
/proc/13695/stat : 13695 (aspuncud-full) S 13694 13695 1750 0 -1 4202496 693 2807 2 7 0 0 2 1 20 0 1 0 118037276 9433088 364 18446744073709551615 4194304 5129932 140736324905984 140736324904640 139778502558814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13695/statm: 2303 364 303 229 0 63 0
[pid=13708] ppid=13695 vsize=98072 CPUtime=2.76
/proc/13708/stat : 13708 (cudf2lp) R 13695 13695 1750 0 -1 4202496 22577 0 1 0 264 12 0 0 20 0 1 0 118037287 100425728 19179 18446744073709551615 4194304 5690517 140734380278192 140734380274392 4363496 0 0 16781316 0 0 0 0 17 0 0 0 19 0 0
/proc/13708/statm: 24518 19179 160 366 0 24149 0
Current children cumulated CPU time (s) 2.79
Current children cumulated vsize (KiB) 107284

[startup+6.30026 s]
/proc/loadavg: 1.03 1.03 1.00 2/61 13709
/proc/meminfo: memFree=435008/1022884 swapFree=0/0
[pid=13695] ppid=13694 vsize=9212 CPUtime=4.57
/proc/13695/stat : 13695 (aspuncud-full) S 13694 13695 1750 0 -1 4202496 720 44083 2 8 0 0 430 27 20 0 1 0 118037276 9433088 364 18446744073709551615 4194304 5129932 140736324905984 140736324904640 139778502558814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13695/statm: 2303 364 303 229 0 63 0
[pid=13709] ppid=13695 vsize=55880 CPUtime=1.33
/proc/13709/stat : 13709 (gringo) R 13695 13695 1750 0 -1 4202496 16077 0 1 0 124 9 0 0 20 0 1 0 118037767 57221120 11920 18446744073709551615 4194304 6531320 140734724805376 140734724801560 5507368 0 0 16781316 16386 0 0 0 17 0 0 0 4 0 0
/proc/13709/statm: 13970 11920 259 571 0 13391 0
Current children cumulated CPU time (s) 5.9
Current children cumulated vsize (KiB) 65092

[startup+12.7003 s]
/proc/loadavg: 1.02 1.03 1.00 2/62 13711
/proc/meminfo: memFree=375504/1022884 swapFree=0/0
[pid=13695] ppid=13694 vsize=9212 CPUtime=11.24
/proc/13695/stat : 13695 (aspuncud-full) S 13694 13695 1750 0 -1 4202496 759 182968 2 9 0 0 1039 85 20 0 1 0 118037276 9433088 364 18446744073709551615 4194304 5129932 140736324905984 140736324904048 139778502558814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13695/statm: 2303 364 303 229 0 63 0
[pid=13710] ppid=13695 vsize=175344 CPUtime=0.92
/proc/13710/stat : 13710 (unclasp) R 13695 13695 1750 0 -1 4202496 48462 0 0 0 76 16 0 0 20 0 1 0 118038451 179552256 42227 18446744073709551615 4194304 6012874 140734954902208 140734954900968 4275701 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13710/statm: 43836 42227 201 444 0 43384 0
[pid=13711] ppid=13695 vsize=22040 CPUtime=0.01
/proc/13711/stat : 13711 (parse.py) S 13695 13695 1750 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 118038451 22568960 1127 18446744073709551615 4194304 6642060 140734867051776 140734867050136 140419548694304 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/13711/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 12.17
Current children cumulated vsize (KiB) 206596

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

[startup+12.8004 s]
/proc/loadavg: 1.02 1.03 1.00 2/62 13711
/proc/meminfo: memFree=375504/1022884 swapFree=0/0
[pid=13695] ppid=13694 vsize=9212 CPUtime=11.24
/proc/13695/stat : 13695 (aspuncud-full) S 13694 13695 1750 0 -1 4202496 759 182968 2 9 0 0 1039 85 20 0 1 0 118037276 9433088 364 18446744073709551615 4194304 5129932 140736324905984 140736324904048 139778502558814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13695/statm: 2303 364 303 229 0 63 0
[pid=13710] ppid=13695 vsize=163040 CPUtime=1.02
/proc/13710/stat : 13710 (unclasp) R 13695 13695 1750 0 -1 4202496 48517 0 0 0 86 16 0 0 20 0 1 0 118038451 166952960 39946 18446744073709551615 4194304 6012874 140734954902208 140734954901384 5251042 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13710/statm: 40760 39946 225 444 0 40308 0
[pid=13711] ppid=13695 vsize=22188 CPUtime=0.01
/proc/13711/stat : 13711 (parse.py) S 13695 13695 1750 0 -1 4202496 1331 0 0 0 0 1 0 0 20 0 1 0 118038451 22720512 1140 18446744073709551615 4194304 6642060 140734867051776 140734867049784 140419548694304 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/13711/statm: 5547 1140 508 598 0 633 0
Current children cumulated CPU time (s) 12.27
Current children cumulated vsize (KiB) 194440

[startup+13.0007 s]
/proc/loadavg: 1.02 1.03 1.00 2/62 13711
/proc/meminfo: memFree=375504/1022884 swapFree=0/0
[pid=13695] ppid=13694 vsize=9212 CPUtime=11.24
/proc/13695/stat : 13695 (aspuncud-full) S 13694 13695 1750 0 -1 4202496 759 182968 2 9 0 0 1039 85 20 0 1 0 118037276 9433088 364 18446744073709551615 4194304 5129932 140736324905984 140736324904048 139778502558814 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13695/statm: 2303 364 303 229 0 63 0
[pid=13710] ppid=13695 vsize=163040 CPUtime=1.21
/proc/13710/stat : 13710 (unclasp) R 13695 13695 1750 0 -1 4202496 48527 0 0 0 102 19 0 0 20 0 1 0 118038451 166952960 14356 18446744073709551615 4194304 6012874 140734954902208 140734954901608 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13710/statm: 40760 14356 234 444 0 40308 0
[pid=13711] ppid=13695 vsize=22336 CPUtime=0.01
/proc/13711/stat : 13711 (parse.py) S 13695 13695 1750 0 -1 4202496 1366 0 0 0 0 1 0 0 20 0 1 0 118038451 22872064 1175 18446744073709551615 4194304 6642060 140734867051776 140734867050056 140419548694304 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/13711/statm: 5584 1175 508 598 0 670 0
Current children cumulated CPU time (s) 12.46
Current children cumulated vsize (KiB) 194588

Child status: 0
Real time (s): 13.03
CPU time (s): 12.5208
CPU user time (s): 11.4327
CPU system time (s): 1.08807
CPU usage (%): 96.0923
Max. virtual memory (cumulated for all children) (KiB): 599840

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 11.4327
system time used= 1.08807
maximum resident set size= 481540
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 233906
page faults= 11
swaps= 0
block input operations= 69192
block output operations= 66960
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 161
involuntary context switches= 1824

runsolver used 0.016001 second user time and 0.060003 second system time

The end