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/upgrade/difficult/rand752.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/difficult/rand752.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/upgrade/upgrade/difficult/rand752.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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 0.87 0.92 0.55 2/60 9687
/proc/meminfo: memFree=151600/1022884 swapFree=0/0
[pid=9687] ppid=9686 vsize=9204 CPUtime=0
/proc/9687/stat : 9687 (aspcud-full) S 9686 9687 1750 0 -1 4202496 432 0 0 0 0 0 0 0 20 0 1 0 117115090 9424896 332 18446744073709551615 4194304 5129932 140736116160912 140736116158376 140195056650016 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/9687/statm: 2301 332 272 229 0 61 0

[startup+0.177103 s]
/proc/loadavg: 0.87 0.92 0.55 2/60 9687
/proc/meminfo: memFree=151600/1022884 swapFree=0/0
[pid=9687] ppid=9686 vsize=9212 CPUtime=0.04
/proc/9687/stat : 9687 (aspcud-full) S 9686 9687 1750 0 -1 4202496 739 3623 0 0 0 0 2 2 20 0 1 0 117115090 9433088 365 18446744073709551615 4194304 5129932 140736116160912 140736116159568 140195056505950 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9687/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200273 s]
/proc/loadavg: 0.87 0.92 0.55 2/60 9687
/proc/meminfo: memFree=151600/1022884 swapFree=0/0
[pid=9687] ppid=9686 vsize=9212 CPUtime=0.04
/proc/9687/stat : 9687 (aspcud-full) S 9686 9687 1750 0 -1 4202496 739 3623 0 0 0 0 2 2 20 0 1 0 117115090 9433088 365 18446744073709551615 4194304 5129932 140736116160912 140736116159568 140195056505950 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9687/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300256 s]
/proc/loadavg: 0.87 0.92 0.55 2/60 9687
/proc/meminfo: memFree=151600/1022884 swapFree=0/0
[pid=9687] ppid=9686 vsize=9212 CPUtime=0.04
/proc/9687/stat : 9687 (aspcud-full) S 9686 9687 1750 0 -1 4202496 739 3623 0 0 0 0 2 2 20 0 1 0 117115090 9433088 365 18446744073709551615 4194304 5129932 140736116160912 140736116159568 140195056505950 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9687/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.70023 s]
/proc/loadavg: 0.87 0.92 0.55 2/60 9687
/proc/meminfo: memFree=151600/1022884 swapFree=0/0
[pid=9687] ppid=9686 vsize=9212 CPUtime=0.04
/proc/9687/stat : 9687 (aspcud-full) S 9686 9687 1750 0 -1 4202496 739 3623 0 0 0 0 2 2 20 0 1 0 117115090 9433088 365 18446744073709551615 4194304 5129932 140736116160912 140736116159568 140195056505950 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9687/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 0.88 0.92 0.55 2/62 9703
/proc/meminfo: memFree=115616/1022884 swapFree=0/0
[pid=9687] ppid=9686 vsize=9212 CPUtime=0.04
/proc/9687/stat : 9687 (aspcud-full) S 9686 9687 1750 0 -1 4202496 739 3623 0 0 0 0 2 2 20 0 1 0 117115090 9433088 365 18446744073709551615 4194304 5129932 140736116160912 140736116159568 140195056505950 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9687/statm: 2303 365 303 229 0 63 0
[pid=9703] ppid=9687 vsize=34564 CPUtime=1.3
/proc/9703/stat : 9703 (cudf2lp) R 9687 9687 1750 0 -1 4202496 10078 0 0 0 128 2 0 0 20 0 1 0 117115093 35393536 8344 18446744073709551615 4194304 5690517 140733285976272 140733285973912 4817317 0 0 16781316 0 0 0 0 17 0 0 0 14 0 0
/proc/9703/statm: 8641 8344 160 366 0 8272 0
Current children cumulated CPU time (s) 1.34
Current children cumulated vsize (KiB) 43776

[startup+3.10032 s]
/proc/loadavg: 0.88 0.92 0.55 2/62 9703
/proc/meminfo: memFree=82880/1022884 swapFree=0/0
[pid=9687] ppid=9686 vsize=9212 CPUtime=0.04
/proc/9687/stat : 9687 (aspcud-full) S 9686 9687 1750 0 -1 4202496 739 3623 0 0 0 0 2 2 20 0 1 0 117115090 9433088 365 18446744073709551615 4194304 5129932 140736116160912 140736116159568 140195056505950 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9687/statm: 2303 365 303 229 0 63 0
[pid=9703] ppid=9687 vsize=99148 CPUtime=2.89
/proc/9703/stat : 9703 (cudf2lp) R 9687 9687 1750 0 -1 4202496 27983 0 0 0 274 15 0 0 20 0 1 0 117115093 101527552 21255 18446744073709551615 4194304 5690517 140733285976272 140733285973912 4382131 0 0 16781316 0 0 0 0 17 0 0 0 14 0 0
/proc/9703/statm: 24787 21255 160 366 0 24418 0
Current children cumulated CPU time (s) 2.93
Current children cumulated vsize (KiB) 108360

[startup+6.30027 s]
/proc/loadavg: 0.89 0.92 0.55 2/62 9704
/proc/meminfo: memFree=108052/1022884 swapFree=0/0
[pid=9687] ppid=9686 vsize=9212 CPUtime=4.6
/proc/9687/stat : 9687 (aspcud-full) S 9686 9687 1750 0 -1 4202496 763 44903 0 0 0 0 430 30 20 0 1 0 117115090 9433088 365 18446744073709551615 4194304 5129932 140736116160912 140736116159568 140195056505950 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9687/statm: 2303 365 303 229 0 63 0
[pid=9704] ppid=9687 vsize=58568 CPUtime=1.4
/proc/9704/stat : 9704 (gringo) R 9687 9687 1750 0 -1 4202496 16909 0 0 0 135 5 0 0 20 0 1 0 117115578 59973632 12750 18446744073709551615 4194304 6531320 140733988780768 140733988776952 5058553 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/9704/statm: 14642 12750 259 571 0 14063 0
Current children cumulated CPU time (s) 6
Current children cumulated vsize (KiB) 67780

[startup+12.7004 s]
/proc/loadavg: 0.90 0.92 0.55 2/63 9706
/proc/meminfo: memFree=418520/1022884 swapFree=0/0
[pid=9687] ppid=9686 vsize=9212 CPUtime=11.18
/proc/9687/stat : 9687 (aspcud-full) S 9686 9687 1750 0 -1 4202496 801 180605 0 0 0 0 1035 83 20 0 1 0 117115090 9433088 365 18446744073709551615 4194304 5129932 140736116160912 140736116158976 140195056505950 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9687/statm: 2303 365 303 229 0 63 0
[pid=9705] ppid=9687 vsize=157656 CPUtime=0.79
/proc/9705/stat : 9705 (clasp) R 9687 9687 1750 0 -1 4202496 43913 0 22 0 64 15 0 0 20 0 1 0 117116260 161439744 37698 18446744073709551615 4194304 6238623 140733623709968 140733623705464 4492792 0 0 16781316 18946 0 0 0 17 0 0 0 19 0 0
/proc/9705/statm: 39414 37698 200 500 0 38911 0
[pid=9706] ppid=9687 vsize=22040 CPUtime=0.02
/proc/9706/stat : 9706 (parse.py) S 9687 9687 1750 0 -1 4202496 1306 0 13 0 0 2 0 0 20 0 1 0 117116260 22568960 1128 18446744073709551615 4194304 6642060 140734837055152 140734837053512 140086352082720 0 0 16777220 20994 0 0 0 17 0 0 0 19 0 0
/proc/9706/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 11.99
Current children cumulated vsize (KiB) 188908

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

[startup+12.8005 s]
/proc/loadavg: 0.90 0.92 0.55 2/63 9706
/proc/meminfo: memFree=418520/1022884 swapFree=0/0
[pid=9687] ppid=9686 vsize=9212 CPUtime=11.18
/proc/9687/stat : 9687 (aspcud-full) S 9686 9687 1750 0 -1 4202496 801 180605 0 0 0 0 1035 83 20 0 1 0 117115090 9433088 365 18446744073709551615 4194304 5129932 140736116160912 140736116158976 140195056505950 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9687/statm: 2303 365 303 229 0 63 0
[pid=9705] ppid=9687 vsize=164504 CPUtime=0.89
/proc/9705/stat : 9705 (clasp) R 9687 9687 1750 0 -1 4202496 45621 0 22 0 73 16 0 0 20 0 1 0 117116260 168452096 39406 18446744073709551615 4194304 6238623 140733623709968 140733623707528 4788467 0 0 16781316 18946 0 0 0 17 0 0 0 19 0 0
/proc/9705/statm: 41126 39406 211 500 0 40623 0
[pid=9706] ppid=9687 vsize=22040 CPUtime=0.02
/proc/9706/stat : 9706 (parse.py) S 9687 9687 1750 0 -1 4202496 1306 0 13 0 0 2 0 0 20 0 1 0 117116260 22568960 1128 18446744073709551615 4194304 6642060 140734837055152 140734837053512 140086352082720 0 0 16777220 20994 0 0 0 17 0 0 0 19 0 0
/proc/9706/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.09
Current children cumulated vsize (KiB) 195756

[startup+14.4075 s]
/proc/loadavg: 0.90 0.92 0.55 2/63 9706
/proc/meminfo: memFree=315600/1022884 swapFree=0/0
[pid=9687] ppid=9686 vsize=9212 CPUtime=11.18
/proc/9687/stat : 9687 (aspcud-full) S 9686 9687 1750 0 -1 4202496 801 180605 0 0 0 0 1035 83 20 0 1 0 117115090 9433088 365 18446744073709551615 4194304 5129932 140736116160912 140736116158976 140195056505950 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9687/statm: 2303 365 303 229 0 63 0
[pid=9705] ppid=9687 vsize=161972 CPUtime=2.47
/proc/9705/stat : 9705 (clasp) R 9687 9687 1750 0 -1 4202496 48108 0 22 0 230 17 0 0 20 0 1 0 117116260 165859328 39624 18446744073709551615 4194304 6238623 140733623709968 140733623707264 5442525 0 0 16781316 18946 0 0 0 17 0 0 0 19 0 0
/proc/9705/statm: 40493 39624 256 500 0 39990 0
[pid=9706] ppid=9687 vsize=22040 CPUtime=0.02
/proc/9706/stat : 9706 (parse.py) S 9687 9687 1750 0 -1 4202496 1306 0 13 0 0 2 0 0 20 0 1 0 117116260 22568960 1128 18446744073709551615 4194304 6642060 140734837055152 140734837053512 140086352082720 0 0 16777220 20994 0 0 0 17 0 0 0 19 0 0
/proc/9706/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 13.67
Current children cumulated vsize (KiB) 193224

[startup+15.2004 s]
/proc/loadavg: 0.90 0.92 0.55 2/63 9706
/proc/meminfo: memFree=315600/1022884 swapFree=0/0
[pid=9687] ppid=9686 vsize=9212 CPUtime=11.18
/proc/9687/stat : 9687 (aspcud-full) S 9686 9687 1750 0 -1 4202496 801 180605 0 0 0 0 1035 83 20 0 1 0 117115090 9433088 365 18446744073709551615 4194304 5129932 140736116160912 140736116158976 140195056505950 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9687/statm: 2303 365 303 229 0 63 0
[pid=9705] ppid=9687 vsize=161972 CPUtime=3.26
/proc/9705/stat : 9705 (clasp) R 9687 9687 1750 0 -1 4202496 48116 0 22 0 309 17 0 0 20 0 1 0 117116260 165859328 39632 18446744073709551615 4194304 6238623 140733623709968 140733623706992 4356242 0 0 16781316 18946 0 0 0 17 0 0 0 19 0 0
/proc/9705/statm: 40493 39632 264 500 0 39990 0
[pid=9706] ppid=9687 vsize=22040 CPUtime=0.02
/proc/9706/stat : 9706 (parse.py) S 9687 9687 1750 0 -1 4202496 1306 0 13 0 0 2 0 0 20 0 1 0 117116260 22568960 1128 18446744073709551615 4194304 6642060 140734837055152 140734837053512 140086352082720 0 0 16777220 20994 0 0 0 17 0 0 0 19 0 0
/proc/9706/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 14.46
Current children cumulated vsize (KiB) 193224

[startup+16.0004 s]
/proc/loadavg: 0.90 0.92 0.55 2/63 9706
/proc/meminfo: memFree=315600/1022884 swapFree=0/0
[pid=9687] ppid=9686 vsize=9212 CPUtime=11.18
/proc/9687/stat : 9687 (aspcud-full) S 9686 9687 1750 0 -1 4202496 801 180605 0 0 0 0 1035 83 20 0 1 0 117115090 9433088 365 18446744073709551615 4194304 5129932 140736116160912 140736116158976 140195056505950 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9687/statm: 2303 365 303 229 0 63 0
[pid=9705] ppid=9687 vsize=161972 CPUtime=4.06
/proc/9705/stat : 9705 (clasp) R 9687 9687 1750 0 -1 4202496 48116 0 22 0 388 18 0 0 20 0 1 0 117116260 165859328 39632 18446744073709551615 4194304 6238623 140733623709968 140733623706992 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 19 0 0
/proc/9705/statm: 40493 39632 264 500 0 39990 0
[pid=9706] ppid=9687 vsize=22040 CPUtime=0.02
/proc/9706/stat : 9706 (parse.py) S 9687 9687 1750 0 -1 4202496 1306 0 13 0 0 2 0 0 20 0 1 0 117116260 22568960 1128 18446744073709551615 4194304 6642060 140734837055152 140734837053512 140086352082720 0 0 16777220 20994 0 0 0 17 0 0 0 19 0 0
/proc/9706/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 15.26
Current children cumulated vsize (KiB) 193224

[startup+16.4004 s]
/proc/loadavg: 0.90 0.92 0.55 2/63 9706
/proc/meminfo: memFree=315600/1022884 swapFree=0/0
[pid=9687] ppid=9686 vsize=9212 CPUtime=15.66
/proc/9687/stat : 9687 (aspcud-full) S 9686 9687 1750 0 -1 4202496 837 230063 0 35 0 0 1456 110 20 0 1 0 117115090 9433088 365 18446744073709551615 4194304 5129932 140736116160912 140736116158464 140195056505950 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9687/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 15.66
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 16.4212
CPU time (s): 15.681
CPU user time (s): 14.5689
CPU system time (s): 1.11207
CPU usage (%): 95.4925
Max. virtual memory (cumulated for all children) (KiB): 587204

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 14.5689
system time used= 1.11207
maximum resident set size= 468800
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 231135
page faults= 36
swaps= 0
block input operations= 73480
block output operations= 65408
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 128
involuntary context switches= 2079

runsolver used 0.028001 second user time and 0.080005 second system time

The end