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 150 -d 10 -w /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/paranoid-size/real/978532fa-c730-11df-b070-00163e3d3b7c.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/real/978532fa-c730-11df-b070-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/paranoid-size/real/978532fa-c730-11df-b070-00163e3d3b7c.cudf.result -count(removed),-sum(solution,installedsize),-count(changed) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 150 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 180 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: 0.94 0.92 0.69 2/60 3405
/proc/meminfo: memFree=416844/1022884 swapFree=0/0
[pid=3405] ppid=3404 vsize=3152 CPUtime=0
/proc/3405/stat : 3405 (runsolver) R 3404 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115242799 3227648 32 18446744073709551615 134512640 134586868 4288877216 4288875264 4151628848 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/3405/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.20253 s]
/proc/loadavg: 0.94 0.92 0.69 2/60 3405
/proc/meminfo: memFree=416844/1022884 swapFree=0/0
[pid=3405] ppid=3404 vsize=9212 CPUtime=0.05
/proc/3405/stat : 3405 (aspcud-basic) S 3404 3405 1750 0 -1 4202496 736 3617 0 0 0 1 3 1 20 0 1 0 115242799 9433088 365 18446744073709551615 4194304 5129932 140735985892064 140735985890720 140166437270622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3405/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300318 s]
/proc/loadavg: 0.94 0.92 0.69 2/60 3405
/proc/meminfo: memFree=416844/1022884 swapFree=0/0
[pid=3405] ppid=3404 vsize=9212 CPUtime=0.05
/proc/3405/stat : 3405 (aspcud-basic) S 3404 3405 1750 0 -1 4202496 736 3617 0 0 0 1 3 1 20 0 1 0 115242799 9433088 365 18446744073709551615 4194304 5129932 140735985892064 140735985890720 140166437270622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3405/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.400304 s]
/proc/loadavg: 0.94 0.92 0.69 2/60 3405
/proc/meminfo: memFree=416844/1022884 swapFree=0/0
[pid=3405] ppid=3404 vsize=9212 CPUtime=0.05
/proc/3405/stat : 3405 (aspcud-basic) S 3404 3405 1750 0 -1 4202496 736 3617 0 0 0 1 3 1 20 0 1 0 115242799 9433088 365 18446744073709551615 4194304 5129932 140735985892064 140735985890720 140166437270622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3405/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700218 s]
/proc/loadavg: 0.94 0.92 0.69 2/60 3405
/proc/meminfo: memFree=416844/1022884 swapFree=0/0
[pid=3405] ppid=3404 vsize=9212 CPUtime=0.05
/proc/3405/stat : 3405 (aspcud-basic) S 3404 3405 1750 0 -1 4202496 736 3617 0 0 0 1 3 1 20 0 1 0 115242799 9433088 365 18446744073709551615 4194304 5129932 140735985892064 140735985890720 140166437270622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3405/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 0.94 0.92 0.69 2/62 3421
/proc/meminfo: memFree=377264/1022884 swapFree=0/0
[pid=3405] ppid=3404 vsize=9212 CPUtime=0.05
/proc/3405/stat : 3405 (aspcud-basic) S 3404 3405 1750 0 -1 4202496 736 3617 0 0 0 1 3 1 20 0 1 0 115242799 9433088 365 18446744073709551615 4194304 5129932 140735985892064 140735985890720 140166437270622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3405/statm: 2303 365 303 229 0 63 0
[pid=3421] ppid=3405 vsize=51500 CPUtime=1.43
/proc/3421/stat : 3421 (cudf2lp) R 3405 3405 1750 0 -1 4202496 14430 0 0 0 137 6 0 0 20 0 1 0 115242803 52736000 11032 18446744073709551615 4194304 5690517 140736761937552 140736761935192 4970627 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/3421/statm: 12875 11032 160 366 0 12506 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 60712

[startup+3.10032 s]
/proc/loadavg: 0.94 0.92 0.69 2/62 3421
/proc/meminfo: memFree=325804/1022884 swapFree=0/0
[pid=3405] ppid=3404 vsize=9212 CPUtime=3.04
/proc/3405/stat : 3405 (aspcud-basic) S 3404 3405 1750 0 -1 4202496 761 29058 0 0 0 1 286 17 20 0 1 0 115242799 9433088 365 18446744073709551615 4194304 5129932 140735985892064 140735985890720 140166437270622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3405/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 3.04
Current children cumulated vsize (KiB) 9212

[startup+6.3003 s]
/proc/loadavg: 0.94 0.92 0.69 2/62 3422
/proc/meminfo: memFree=272360/1022884 swapFree=0/0
[pid=3405] ppid=3404 vsize=9212 CPUtime=3.04
/proc/3405/stat : 3405 (aspcud-basic) S 3404 3405 1750 0 -1 4202496 761 29058 0 0 0 1 286 17 20 0 1 0 115242799 9433088 365 18446744073709551615 4194304 5129932 140735985892064 140735985890720 140166437270622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3405/statm: 2303 365 303 229 0 63 0
[pid=3422] ppid=3405 vsize=164224 CPUtime=3.19
/proc/3422/stat : 3422 (gringo) R 3405 3405 1750 0 -1 4202496 40052 0 0 0 305 14 0 0 20 0 1 0 115243107 168165376 35383 18446744073709551615 4194304 6531320 140736920335312 140736920331928 4586736 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/3422/statm: 41056 35383 282 571 0 40477 0
Current children cumulated CPU time (s) 6.23
Current children cumulated vsize (KiB) 173436

[startup+12.7003 s]
/proc/loadavg: 0.95 0.92 0.70 2/63 3424
/proc/meminfo: memFree=266108/1022884 swapFree=0/0
[pid=3405] ppid=3404 vsize=9212 CPUtime=9.97
/proc/3405/stat : 3405 (aspcud-basic) S 3404 3405 1750 0 -1 4202496 800 137425 0 0 0 1 935 61 20 0 1 0 115242799 9433088 365 18446744073709551615 4194304 5129932 140735985892064 140735985890128 140166437270622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3405/statm: 2303 365 303 229 0 63 0
[pid=3423] ppid=3405 vsize=140960 CPUtime=2.51
/proc/3423/stat : 3423 (clasp) R 3405 3405 1750 0 -1 4202496 40958 0 0 0 241 10 0 0 20 0 1 0 115243814 144343040 34753 18446744073709551615 4194304 6238623 140735253559616 140735253556640 4635076 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3423/statm: 35240 34753 263 500 0 34737 0
[pid=3424] ppid=3405 vsize=22040 CPUtime=0
/proc/3424/stat : 3424 (parse.py) S 3405 3405 1750 0 -1 4202496 1311 0 9 0 0 0 0 0 20 0 1 0 115243814 22568960 1128 18446744073709551615 4194304 6642060 140734299819040 140734299817400 140062464259872 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/3424/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.48
Current children cumulated vsize (KiB) 172212

[startup+25.5032 s]
/proc/loadavg: 0.96 0.92 0.70 2/63 3424
/proc/meminfo: memFree=265612/1022884 swapFree=0/0
[pid=3405] ppid=3404 vsize=9212 CPUtime=9.97
/proc/3405/stat : 3405 (aspcud-basic) S 3404 3405 1750 0 -1 4202496 800 137425 0 0 0 1 935 61 20 0 1 0 115242799 9433088 365 18446744073709551615 4194304 5129932 140735985892064 140735985890128 140166437270622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3405/statm: 2303 365 303 229 0 63 0
[pid=3423] ppid=3405 vsize=140960 CPUtime=15.21
/proc/3423/stat : 3423 (clasp) R 3405 3405 1750 0 -1 4202496 41119 0 0 0 1511 10 0 0 20 0 1 0 115243814 144343040 34914 18446744073709551615 4194304 6238623 140735253559616 140735253556640 4331924 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3423/statm: 35240 34914 263 500 0 34737 0
[pid=3424] ppid=3405 vsize=22040 CPUtime=0
/proc/3424/stat : 3424 (parse.py) S 3405 3405 1750 0 -1 4202496 1311 0 9 0 0 0 0 0 20 0 1 0 115243814 22568960 1128 18446744073709551615 4194304 6642060 140734299819040 140734299817400 140062464259872 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/3424/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.18
Current children cumulated vsize (KiB) 172212

[startup+51.1003 s]
/proc/loadavg: 0.97 0.93 0.71 2/63 3424
/proc/meminfo: memFree=114456/1022884 swapFree=0/0
[pid=3405] ppid=3404 vsize=9212 CPUtime=9.97
/proc/3405/stat : 3405 (aspcud-basic) S 3404 3405 1750 0 -1 4202496 800 137425 0 0 0 1 935 61 20 0 1 0 115242799 9433088 365 18446744073709551615 4194304 5129932 140735985892064 140735985890128 140166437270622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3405/statm: 2303 365 303 229 0 63 0
[pid=3423] ppid=3405 vsize=291944 CPUtime=40.62
/proc/3423/stat : 3423 (clasp) R 3405 3405 1750 0 -1 4202496 78862 0 0 0 4037 25 0 0 20 0 1 0 115243814 298950656 72656 18446744073709551615 4194304 6238623 140735253559616 140735253556168 4687704 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3423/statm: 72986 72656 264 500 0 72483 0
[pid=3424] ppid=3405 vsize=22040 CPUtime=0
/proc/3424/stat : 3424 (parse.py) S 3405 3405 1750 0 -1 4202496 1311 0 9 0 0 0 0 0 20 0 1 0 115243814 22568960 1128 18446744073709551615 4194304 6642060 140734299819040 140734299817400 140062464259872 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/3424/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.59
Current children cumulated vsize (KiB) 323196

[startup+102.3 s]
/proc/loadavg: 0.99 0.94 0.72 2/63 3424
/proc/meminfo: memFree=97596/1022884 swapFree=0/0
[pid=3405] ppid=3404 vsize=9212 CPUtime=9.97
/proc/3405/stat : 3405 (aspcud-basic) S 3404 3405 1750 0 -1 4202496 800 137425 0 0 0 1 935 61 20 0 1 0 115242799 9433088 365 18446744073709551615 4194304 5129932 140735985892064 140735985890128 140166437270622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3405/statm: 2303 365 303 229 0 63 0
[pid=3423] ppid=3405 vsize=308700 CPUtime=91.46
/proc/3423/stat : 3423 (clasp) R 3405 3405 1750 0 -1 4202496 83046 0 0 0 9120 26 0 0 20 0 1 0 115243814 316108800 76840 18446744073709551615 4194304 6238623 140735253559616 140735253556168 4687704 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3423/statm: 77175 76840 264 500 0 76672 0
[pid=3424] ppid=3405 vsize=22040 CPUtime=0
/proc/3424/stat : 3424 (parse.py) S 3405 3405 1750 0 -1 4202496 1311 0 9 0 0 0 0 0 20 0 1 0 115243814 22568960 1128 18446744073709551615 4194304 6642060 140734299819040 140734299817400 140062464259872 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/3424/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.43
Current children cumulated vsize (KiB) 339952



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.3 s]
/proc/loadavg: 0.99 0.94 0.73 2/63 3424
/proc/meminfo: memFree=67216/1022884 swapFree=0/0
[pid=3405] ppid=3404 vsize=9212 CPUtime=9.97
/proc/3405/stat : 3405 (aspcud-basic) S 3404 3405 1750 0 -1 4202496 800 137425 0 0 0 1 935 61 20 0 1 0 115242799 9433088 365 18446744073709551615 4194304 5129932 140735985892064 140735985890128 140166437270622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3405/statm: 2303 365 303 229 0 63 0
[pid=3423] ppid=3405 vsize=338816 CPUtime=140.11
/proc/3423/stat : 3423 (clasp) R 3405 3405 1750 0 -1 4202496 90601 0 0 0 13982 29 0 0 20 0 1 0 115243814 346947584 84395 18446744073709551615 4194304 6238623 140735253559616 140735253556168 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3423/statm: 84704 84395 264 500 0 84201 0
[pid=3424] ppid=3405 vsize=22040 CPUtime=0
/proc/3424/stat : 3424 (parse.py) S 3405 3405 1750 0 -1 4202496 1311 0 9 0 0 0 0 0 20 0 1 0 115243814 22568960 1128 18446744073709551615 4194304 6642060 140734299819040 140734299817400 140062464259872 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/3424/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 150.08
Current children cumulated vsize (KiB) 370068

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

[startup+151.3 s]
/proc/loadavg: 0.99 0.94 0.73 2/63 3424
/proc/meminfo: memFree=67216/1022884 swapFree=0/0
[pid=3405] ppid=3404 vsize=9212 CPUtime=9.97
/proc/3405/stat : 3405 (aspcud-basic) S 3404 3405 1750 0 -1 4202496 800 137425 0 0 0 1 935 61 20 0 1 0 115242799 9433088 365 18446744073709551615 4194304 5129932 140735985892064 140735985890128 140166437270622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3405/statm: 2303 365 303 229 0 63 0
[pid=3423] ppid=3405 vsize=338816 CPUtime=140.11
/proc/3423/stat : 3423 (clasp) R 3405 3405 1750 0 -1 4202496 90601 0 0 0 13982 29 0 0 20 0 1 0 115243814 346947584 84395 18446744073709551615 4194304 6238623 140735253559616 140735253556168 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3423/statm: 84704 84395 264 500 0 84201 0
[pid=3424] ppid=3405 vsize=22040 CPUtime=0
/proc/3424/stat : 3424 (parse.py) S 3405 3405 1750 0 -1 4202496 1311 0 9 0 0 0 0 0 20 0 1 0 115243814 22568960 1128 18446744073709551615 4194304 6642060 140734299819040 140734299817400 140062464259872 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/3424/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 150.08
Current children cumulated vsize (KiB) 370068

Child status: 0
Real time (s): 151.41
CPU time (s): 150.161
CPU user time (s): 149.201
CPU system time (s): 0.96006
CPU usage (%): 99.1757
Max. virtual memory (cumulated for all children) (KiB): 473116

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.201
system time used= 0.96006
maximum resident set size= 398388
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 230491
page faults= 10
swaps= 0
block input operations= 44736
block output operations= 46600
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 99
involuntary context switches= 17256

runsolver used 0.244015 second user time and 0.588036 second system time

The end