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/real/adf7b774-9af8-11df-bc37-00163e46d37a.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/real/adf7b774-9af8-11df-bc37-00163e46d37a.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/dist-upgrade/real/adf7b774-9af8-11df-bc37-00163e46d37a.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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.00 1.03 1.00 2/59 13475
/proc/meminfo: memFree=264456/1022884 swapFree=0/0
[pid=13475] ppid=13474 vsize=9204 CPUtime=0
/proc/13475/stat : 13475 (aspuncud-full) S 13474 13475 1750 0 -1 4202496 430 0 0 0 0 0 0 0 20 0 1 0 118025898 9424896 331 18446744073709551615 4194304 5129932 140735331906400 140735331903864 140219028178720 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/13475/statm: 2301 331 272 229 0 61 0

[startup+0.135663 s]
/proc/loadavg: 1.00 1.03 1.00 2/59 13475
/proc/meminfo: memFree=264456/1022884 swapFree=0/0
[pid=13475] ppid=13474 vsize=9212 CPUtime=0.04
/proc/13475/stat : 13475 (aspuncud-full) S 13474 13475 1750 0 -1 4202496 701 2807 0 0 0 0 3 1 20 0 1 0 118025898 9433088 364 18446744073709551615 4194304 5129932 140735331906400 140735331905056 140219028034654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13475/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200351 s]
/proc/loadavg: 1.00 1.03 1.00 2/59 13475
/proc/meminfo: memFree=264456/1022884 swapFree=0/0
[pid=13475] ppid=13474 vsize=9212 CPUtime=0.04
/proc/13475/stat : 13475 (aspuncud-full) S 13474 13475 1750 0 -1 4202496 701 2807 0 0 0 0 3 1 20 0 1 0 118025898 9433088 364 18446744073709551615 4194304 5129932 140735331906400 140735331905056 140219028034654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13475/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300319 s]
/proc/loadavg: 1.00 1.03 1.00 2/59 13475
/proc/meminfo: memFree=264456/1022884 swapFree=0/0
[pid=13475] ppid=13474 vsize=9212 CPUtime=0.04
/proc/13475/stat : 13475 (aspuncud-full) S 13474 13475 1750 0 -1 4202496 701 2807 0 0 0 0 3 1 20 0 1 0 118025898 9433088 364 18446744073709551615 4194304 5129932 140735331906400 140735331905056 140219028034654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13475/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700308 s]
/proc/loadavg: 1.00 1.03 1.00 2/59 13475
/proc/meminfo: memFree=264456/1022884 swapFree=0/0
[pid=13475] ppid=13474 vsize=9212 CPUtime=0.04
/proc/13475/stat : 13475 (aspuncud-full) S 13474 13475 1750 0 -1 4202496 701 2807 0 0 0 0 3 1 20 0 1 0 118025898 9433088 364 18446744073709551615 4194304 5129932 140735331906400 140735331905056 140219028034654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13475/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50028 s]
/proc/loadavg: 1.00 1.03 1.00 2/61 13488
/proc/meminfo: memFree=227092/1022884 swapFree=0/0
[pid=13475] ppid=13474 vsize=9212 CPUtime=0.04
/proc/13475/stat : 13475 (aspuncud-full) S 13474 13475 1750 0 -1 4202496 701 2807 0 0 0 0 3 1 20 0 1 0 118025898 9433088 364 18446744073709551615 4194304 5129932 140735331906400 140735331905056 140219028034654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13475/statm: 2303 364 303 229 0 63 0
[pid=13488] ppid=13475 vsize=53284 CPUtime=1.4
/proc/13488/stat : 13488 (cudf2lp) R 13475 13475 1750 0 -1 4202496 15105 0 0 0 134 6 0 0 20 0 1 0 118025901 54562816 11707 18446744073709551615 4194304 5690517 140737123908560 140737123906200 4374743 0 0 16781316 0 0 0 0 17 0 0 0 5 0 0
/proc/13488/statm: 13321 11707 160 366 0 12952 0
Current children cumulated CPU time (s) 1.44
Current children cumulated vsize (KiB) 62496

[startup+3.10026 s]
/proc/loadavg: 1.00 1.03 1.00 2/61 13488
/proc/meminfo: memFree=166540/1022884 swapFree=0/0
[pid=13475] ppid=13474 vsize=9212 CPUtime=2.17
/proc/13475/stat : 13475 (aspuncud-full) S 13474 13475 1750 0 -1 4202496 729 26489 0 0 0 0 205 12 20 0 1 0 118025898 9433088 364 18446744073709551615 4194304 5129932 140735331906400 140735331905056 140219028034654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13475/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 2.17
Current children cumulated vsize (KiB) 9212
heavy processes:

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

[startup+3.20873 s]
/proc/loadavg: 1.00 1.03 1.00 2/61 13489
/proc/meminfo: memFree=203616/1022884 swapFree=0/0
[pid=13475] ppid=13474 vsize=9212 CPUtime=2.17
/proc/13475/stat : 13475 (aspuncud-full) S 13474 13475 1750 0 -1 4202496 729 26489 0 0 0 0 205 12 20 0 1 0 118025898 9433088 364 18446744073709551615 4194304 5129932 140735331906400 140735331905056 140219028034654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13475/statm: 2303 364 303 229 0 63 0
[pid=13489] ppid=13475 vsize=47940 CPUtime=0.96
/proc/13489/stat : 13489 (gringo) R 13475 13475 1750 0 -1 4202496 13118 0 0 0 91 5 0 0 20 0 1 0 118026122 49090560 10498 18446744073709551615 4194304 6531320 140736162795120 140736162791736 4331582 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13489/statm: 11985 10498 279 571 0 11406 0
Current children cumulated CPU time (s) 3.13
Current children cumulated vsize (KiB) 57152

[startup+4.80028 s]
/proc/loadavg: 1.00 1.03 1.00 2/61 13489
/proc/meminfo: memFree=46500/1022884 swapFree=0/0
[pid=13475] ppid=13474 vsize=9212 CPUtime=2.17
/proc/13475/stat : 13475 (aspuncud-full) S 13474 13475 1750 0 -1 4202496 729 26489 0 0 0 0 205 12 20 0 1 0 118025898 9433088 364 18446744073709551615 4194304 5129932 140735331906400 140735331905056 140219028034654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13475/statm: 2303 364 303 229 0 63 0
[pid=13489] ppid=13475 vsize=242604 CPUtime=2.53
/proc/13489/stat : 13489 (gringo) R 13475 13475 1750 0 -1 4202496 59460 0 0 0 235 18 0 0 20 0 1 0 118026122 248426496 54791 18446744073709551615 4194304 6531320 140736162795120 140736162791880 5520730 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13489/statm: 60651 54791 283 571 0 60072 0
Current children cumulated CPU time (s) 4.7
Current children cumulated vsize (KiB) 251816

[startup+5.20022 s]
/proc/loadavg: 1.00 1.03 1.00 2/61 13489
/proc/meminfo: memFree=46500/1022884 swapFree=0/0
[pid=13475] ppid=13474 vsize=9212 CPUtime=4.91
/proc/13475/stat : 13475 (aspuncud-full) S 13474 13475 1750 0 -1 4202496 768 85953 0 0 0 0 456 35 20 0 1 0 118025898 9433088 364 18446744073709551615 4194304 5129932 140735331906400 140735331904464 140219028034654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13475/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 4.91
Current children cumulated vsize (KiB) 9212

[startup+5.40022 s]
/proc/loadavg: 1.00 1.03 1.00 2/61 13489
/proc/meminfo: memFree=46500/1022884 swapFree=0/0
[pid=13475] ppid=13474 vsize=9212 CPUtime=4.91
/proc/13475/stat : 13475 (aspuncud-full) S 13474 13475 1750 0 -1 4202496 768 85953 0 0 0 0 456 35 20 0 1 0 118025898 9433088 364 18446744073709551615 4194304 5129932 140735331906400 140735331904464 140219028034654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13475/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 4.91
Current children cumulated vsize (KiB) 9212

[startup+5.50022 s]
/proc/loadavg: 1.00 1.03 1.00 2/62 13491
/proc/meminfo: memFree=155976/1022884 swapFree=0/0
[pid=13475] ppid=13474 vsize=9212 CPUtime=4.91
/proc/13475/stat : 13475 (aspuncud-full) S 13474 13475 1750 0 -1 4202496 768 85953 0 0 0 0 456 35 20 0 1 0 118025898 9433088 364 18446744073709551615 4194304 5129932 140735331906400 140735331904464 140219028034654 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13475/statm: 2303 364 303 229 0 63 0
[pid=13490] ppid=13475 vsize=73408 CPUtime=0.45
/proc/13490/stat : 13490 (unclasp) R 13475 13475 1750 0 -1 4202496 21697 0 0 0 39 6 0 0 20 0 1 0 118026399 75169792 17836 18446744073709551615 4194304 6012874 140735545225536 140735545224856 4535488 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13490/statm: 18352 17836 225 444 0 17900 0
[pid=13491] ppid=13475 vsize=22188 CPUtime=0.01
/proc/13491/stat : 13491 (parse.py) S 13475 13475 1750 0 -1 4202496 1329 0 0 0 0 1 0 0 20 0 1 0 118026399 22720512 1139 18446744073709551615 4194304 6642060 140734317654688 140734317652728 139986202187552 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/13491/statm: 5547 1139 508 598 0 633 0
Current children cumulated CPU time (s) 5.37
Current children cumulated vsize (KiB) 104808

Child status: 0
Real time (s): 5.56545
CPU time (s): 5.46834
CPU user time (s): 5.00431
CPU system time (s): 0.464029
CPU usage (%): 98.2551
Max. virtual memory (cumulated for all children) (KiB): 251816

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 5.00431
system time used= 0.464029
maximum resident set size= 219164
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 110079
page faults= 0
swaps= 0
block input operations= 37888
block output operations= 31016
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 116
involuntary context switches= 705

runsolver used 0.016001 second user time and 0.024001 second system time

The end