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/aspcud-full-1.7/upgrade/real/7bf50d1c-9b1b-11df-8b50-00163e46d37a.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/real/7bf50d1c-9b1b-11df-8b50-00163e46d37a.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/upgrade/real/7bf50d1c-9b1b-11df-8b50-00163e46d37a.cudf.result -count(down),-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.04 0.71 0.31 2/60 26525
/proc/meminfo: memFree=343380/1022884 swapFree=0/0
[pid=26525] ppid=26524 vsize=3152 CPUtime=0
/proc/26525/stat : 26525 (runsolver) R 26524 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 117075155 3227648 32 18446744073709551615 134512640 134586868 4286648016 4286646064 4151526448 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/26525/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.17334 s]
/proc/loadavg: 1.04 0.71 0.31 2/60 26525
/proc/meminfo: memFree=343380/1022884 swapFree=0/0
[pid=26525] ppid=26524 vsize=9212 CPUtime=0.05
/proc/26525/stat : 26525 (aspcud-full) S 26524 26525 1733 0 -1 4202496 740 3622 0 0 0 0 3 2 20 0 1 0 117075155 9433088 365 18446744073709551615 4194304 5129932 140735229166384 140735229165040 139887383524446 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26525/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200322 s]
/proc/loadavg: 1.04 0.71 0.31 2/60 26525
/proc/meminfo: memFree=343380/1022884 swapFree=0/0
[pid=26525] ppid=26524 vsize=9212 CPUtime=0.05
/proc/26525/stat : 26525 (aspcud-full) S 26524 26525 1733 0 -1 4202496 740 3622 0 0 0 0 3 2 20 0 1 0 117075155 9433088 365 18446744073709551615 4194304 5129932 140735229166384 140735229165040 139887383524446 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26525/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300315 s]
/proc/loadavg: 1.04 0.71 0.31 2/60 26525
/proc/meminfo: memFree=343380/1022884 swapFree=0/0
[pid=26525] ppid=26524 vsize=9212 CPUtime=0.05
/proc/26525/stat : 26525 (aspcud-full) S 26524 26525 1733 0 -1 4202496 740 3622 0 0 0 0 3 2 20 0 1 0 117075155 9433088 365 18446744073709551615 4194304 5129932 140735229166384 140735229165040 139887383524446 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26525/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700223 s]
/proc/loadavg: 1.04 0.71 0.31 2/60 26525
/proc/meminfo: memFree=343380/1022884 swapFree=0/0
[pid=26525] ppid=26524 vsize=9212 CPUtime=0.05
/proc/26525/stat : 26525 (aspcud-full) S 26524 26525 1733 0 -1 4202496 740 3622 0 0 0 0 3 2 20 0 1 0 117075155 9433088 365 18446744073709551615 4194304 5129932 140735229166384 140735229165040 139887383524446 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26525/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50039 s]
/proc/loadavg: 1.04 0.71 0.31 2/62 26541
/proc/meminfo: memFree=306404/1022884 swapFree=0/0
[pid=26525] ppid=26524 vsize=9212 CPUtime=0.05
/proc/26525/stat : 26525 (aspcud-full) S 26524 26525 1733 0 -1 4202496 740 3622 0 0 0 0 3 2 20 0 1 0 117075155 9433088 365 18446744073709551615 4194304 5129932 140735229166384 140735229165040 139887383524446 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26525/statm: 2303 365 303 229 0 63 0
[pid=26541] ppid=26525 vsize=53320 CPUtime=1.28
/proc/26541/stat : 26541 (cudf2lp) D 26525 26525 1733 0 -1 4202496 14880 0 0 0 123 5 0 0 20 0 1 0 117075158 54599680 11481 18446744073709551615 4194304 5690517 140735814639232 140735814636904 5058400 0 0 16781316 0 0 0 0 17 0 0 0 16 0 0
/proc/26541/statm: 13330 11481 160 366 0 12961 0
Current children cumulated CPU time (s) 1.33
Current children cumulated vsize (KiB) 62532

[startup+3.1002 s]
/proc/loadavg: 1.04 0.71 0.31 2/62 26541
/proc/meminfo: memFree=252588/1022884 swapFree=0/0
[pid=26525] ppid=26524 vsize=9212 CPUtime=2.23
/proc/26525/stat : 26525 (aspcud-full) S 26524 26525 1733 0 -1 4202496 765 27307 0 0 0 0 208 15 20 0 1 0 117075155 9433088 365 18446744073709551615 4194304 5129932 140735229166384 140735229165040 139887383524446 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26525/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 2.23
Current children cumulated vsize (KiB) 9212
heavy processes:

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

[startup+3.20343 s]
/proc/loadavg: 1.04 0.71 0.31 2/62 26542
/proc/meminfo: memFree=293880/1022884 swapFree=0/0
[pid=26525] ppid=26524 vsize=9212 CPUtime=2.23
/proc/26525/stat : 26525 (aspcud-full) S 26524 26525 1733 0 -1 4202496 765 27307 0 0 0 0 208 15 20 0 1 0 117075155 9433088 365 18446744073709551615 4194304 5129932 140735229166384 140735229165040 139887383524446 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26525/statm: 2303 365 303 229 0 63 0
[pid=26542] ppid=26525 vsize=27824 CPUtime=0.62
/proc/26542/stat : 26542 (gringo) R 26525 26525 1733 0 -1 4202496 7932 0 0 0 60 2 0 0 20 0 1 0 117075411 28491776 6370 18446744073709551615 4194304 6531320 140736052772704 140736052768504 4330140 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/26542/statm: 6956 6370 259 571 0 6377 0
Current children cumulated CPU time (s) 2.85
Current children cumulated vsize (KiB) 37036

[startup+4.80026 s]
/proc/loadavg: 1.04 0.71 0.31 2/62 26542
/proc/meminfo: memFree=171120/1022884 swapFree=0/0
[pid=26525] ppid=26524 vsize=9212 CPUtime=2.23
/proc/26525/stat : 26525 (aspcud-full) S 26524 26525 1733 0 -1 4202496 765 27307 0 0 0 0 208 15 20 0 1 0 117075155 9433088 365 18446744073709551615 4194304 5129932 140735229166384 140735229165040 139887383524446 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26525/statm: 2303 365 303 229 0 63 0
[pid=26542] ppid=26525 vsize=217696 CPUtime=2.21
/proc/26542/stat : 26542 (gringo) R 26525 26525 1733 0 -1 4202496 53572 0 0 0 206 15 0 0 20 0 1 0 117075411 222920704 48936 18446744073709551615 4194304 6531320 140736052772704 140736052769320 4331241 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/26542/statm: 54424 48936 282 571 0 53845 0
Current children cumulated CPU time (s) 4.44
Current children cumulated vsize (KiB) 226908

[startup+5.60335 s]
/proc/loadavg: 1.04 0.71 0.31 2/63 26544
/proc/meminfo: memFree=244768/1022884 swapFree=0/0
[pid=26525] ppid=26524 vsize=9212 CPUtime=4.93
/proc/26525/stat : 26525 (aspcud-full) S 26524 26525 1733 0 -1 4202496 803 85396 0 0 0 0 455 38 20 0 1 0 117075155 9433088 365 18446744073709551615 4194304 5129932 140735229166384 140735229164448 139887383524446 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26525/statm: 2303 365 303 229 0 63 0
[pid=26543] ppid=26525 vsize=75512 CPUtime=0.28
/proc/26543/stat : 26543 (clasp) R 26525 26525 1733 0 -1 4202496 20777 0 0 0 23 5 0 0 20 0 1 0 117075684 77324288 17960 18446744073709551615 4194304 6238623 140736074408864 140736074406200 5446660 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26543/statm: 18878 17960 214 500 0 18375 0
[pid=26544] ppid=26525 vsize=22040 CPUtime=0
/proc/26544/stat : 26544 (parse.py) S 26525 26525 1733 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 117075684 22568960 1128 18446744073709551615 4194304 6642060 140734024728288 140734024726648 139841585985312 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/26544/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 5.21
Current children cumulated vsize (KiB) 106764

[startup+6.00033 s]
/proc/loadavg: 1.04 0.71 0.31 2/63 26544
/proc/meminfo: memFree=244768/1022884 swapFree=0/0
[pid=26525] ppid=26524 vsize=9212 CPUtime=4.93
/proc/26525/stat : 26525 (aspcud-full) S 26524 26525 1733 0 -1 4202496 803 85396 0 0 0 0 455 38 20 0 1 0 117075155 9433088 365 18446744073709551615 4194304 5129932 140735229166384 140735229164448 139887383524446 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26525/statm: 2303 365 303 229 0 63 0
[pid=26543] ppid=26525 vsize=72184 CPUtime=0.68
/proc/26543/stat : 26543 (clasp) R 26525 26525 1733 0 -1 4202496 21459 0 0 0 62 6 0 0 20 0 1 0 117075684 73916416 17497 18446744073709551615 4194304 6238623 140736074408864 140736074405888 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26543/statm: 18046 17497 264 500 0 17543 0
[pid=26544] ppid=26525 vsize=22040 CPUtime=0
/proc/26544/stat : 26544 (parse.py) S 26525 26525 1733 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 117075684 22568960 1128 18446744073709551615 4194304 6642060 140734024728288 140734024726648 139841585985312 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/26544/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 5.61
Current children cumulated vsize (KiB) 103436

[startup+6.20033 s]
/proc/loadavg: 1.04 0.71 0.31 2/63 26544
/proc/meminfo: memFree=244768/1022884 swapFree=0/0
[pid=26525] ppid=26524 vsize=9212 CPUtime=4.93
/proc/26525/stat : 26525 (aspcud-full) S 26524 26525 1733 0 -1 4202496 803 85396 0 0 0 0 455 38 20 0 1 0 117075155 9433088 365 18446744073709551615 4194304 5129932 140735229166384 140735229164448 139887383524446 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26525/statm: 2303 365 303 229 0 63 0
[pid=26543] ppid=26525 vsize=72184 CPUtime=0.88
/proc/26543/stat : 26543 (clasp) R 26525 26525 1733 0 -1 4202496 21459 0 0 0 82 6 0 0 20 0 1 0 117075684 73916416 17497 18446744073709551615 4194304 6238623 140736074408864 140736074405888 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26543/statm: 18046 17497 264 500 0 17543 0
[pid=26544] ppid=26525 vsize=22040 CPUtime=0
/proc/26544/stat : 26544 (parse.py) S 26525 26525 1733 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 117075684 22568960 1128 18446744073709551615 4194304 6642060 140734024728288 140734024726648 139841585985312 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/26544/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 5.81
Current children cumulated vsize (KiB) 103436

Child status: 0
Real time (s): 6.2929
CPU time (s): 5.94437
CPU user time (s): 5.46034
CPU system time (s): 0.48403
CPU usage (%): 94.4616
Max. virtual memory (cumulated for all children) (KiB): 246308

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 5.46034
system time used= 0.48403
maximum resident set size= 213796
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 109301
page faults= 0
swaps= 0
block input operations= 37872
block output operations= 30608
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 96
involuntary context switches= 710

runsolver used 0.004 second user time and 0.040002 second system time

The end