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/8b0e7c16-bab4-11e0-a883-00163e1e087d.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/real/8b0e7c16-bab4-11e0-a883-00163e1e087d.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/paranoid-size/real/8b0e7c16-bab4-11e0-a883-00163e1e087d.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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 0.98 0.95 0.78 2/61 6924
/proc/meminfo: memFree=295656/1022884 swapFree=0/0
[pid=6924] ppid=6923 vsize=9204 CPUtime=0
/proc/6924/stat : 6924 (aspcud-basic) S 6923 6924 32685 0 -1 4202496 433 0 0 0 0 0 0 0 20 0 1 0 37062669 9424896 332 18446744073709551615 4194304 5129932 140736997460464 140736997457928 139729694078752 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/6924/statm: 2301 332 272 229 0 61 0

[startup+0.16273 s]
/proc/loadavg: 0.98 0.95 0.78 2/61 6924
/proc/meminfo: memFree=295656/1022884 swapFree=0/0
[pid=6924] ppid=6923 vsize=9212 CPUtime=0.05
/proc/6924/stat : 6924 (aspcud-basic) S 6923 6924 32685 0 -1 4202496 737 3620 0 0 0 0 3 2 20 0 1 0 37062669 9433088 365 18446744073709551615 4194304 5129932 140736997460464 140736997459120 139729693934686 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6924/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200357 s]
/proc/loadavg: 0.98 0.95 0.78 2/61 6924
/proc/meminfo: memFree=295656/1022884 swapFree=0/0
[pid=6924] ppid=6923 vsize=9212 CPUtime=0.05
/proc/6924/stat : 6924 (aspcud-basic) S 6923 6924 32685 0 -1 4202496 737 3620 0 0 0 0 3 2 20 0 1 0 37062669 9433088 365 18446744073709551615 4194304 5129932 140736997460464 140736997459120 139729693934686 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6924/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300307 s]
/proc/loadavg: 0.98 0.95 0.78 2/61 6924
/proc/meminfo: memFree=295656/1022884 swapFree=0/0
[pid=6924] ppid=6923 vsize=9212 CPUtime=0.05
/proc/6924/stat : 6924 (aspcud-basic) S 6923 6924 32685 0 -1 4202496 737 3620 0 0 0 0 3 2 20 0 1 0 37062669 9433088 365 18446744073709551615 4194304 5129932 140736997460464 140736997459120 139729693934686 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6924/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700231 s]
/proc/loadavg: 0.98 0.95 0.78 2/61 6924
/proc/meminfo: memFree=295656/1022884 swapFree=0/0
[pid=6924] ppid=6923 vsize=9212 CPUtime=0.05
/proc/6924/stat : 6924 (aspcud-basic) S 6923 6924 32685 0 -1 4202496 737 3620 0 0 0 0 3 2 20 0 1 0 37062669 9433088 365 18446744073709551615 4194304 5129932 140736997460464 140736997459120 139729693934686 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6924/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 0.98 0.95 0.78 2/63 6940
/proc/meminfo: memFree=259052/1022884 swapFree=0/0
[pid=6924] ppid=6923 vsize=9212 CPUtime=0.05
/proc/6924/stat : 6924 (aspcud-basic) S 6923 6924 32685 0 -1 4202496 737 3620 0 0 0 0 3 2 20 0 1 0 37062669 9433088 365 18446744073709551615 4194304 5129932 140736997460464 140736997459120 139729693934686 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6924/statm: 2303 365 303 229 0 63 0
[pid=6940] ppid=6924 vsize=50452 CPUtime=1.42
/proc/6940/stat : 6940 (cudf2lp) R 6924 6924 32685 0 -1 4202496 14255 0 0 0 134 8 0 0 20 0 1 0 37062673 51662848 10856 18446744073709551615 4194304 5690517 140733713328336 140733713325976 4357582 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/6940/statm: 12613 10856 160 366 0 12244 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 59664

[startup+3.10032 s]
/proc/loadavg: 0.98 0.95 0.78 2/63 6940
/proc/meminfo: memFree=226068/1022884 swapFree=0/0
[pid=6924] ppid=6923 vsize=9212 CPUtime=0.05
/proc/6924/stat : 6924 (aspcud-basic) S 6923 6924 32685 0 -1 4202496 737 3620 0 0 0 0 3 2 20 0 1 0 37062669 9433088 365 18446744073709551615 4194304 5129932 140736997460464 140736997459120 139729693934686 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6924/statm: 2303 365 303 229 0 63 0
[pid=6940] ppid=6924 vsize=84504 CPUtime=3.01
/proc/6940/stat : 6940 (cudf2lp) R 6924 6924 32685 0 -1 4202496 27255 0 0 0 284 17 0 0 20 0 1 0 37062673 86532096 20854 18446744073709551615 4194304 5690517 140733713328336 140733713325704 4951926 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/6940/statm: 21126 20854 174 366 0 20757 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 93716

[startup+6.30032 s]
/proc/loadavg: 0.98 0.95 0.79 2/63 6941
/proc/meminfo: memFree=161216/1022884 swapFree=0/0
[pid=6924] ppid=6923 vsize=9212 CPUtime=3.15
/proc/6924/stat : 6924 (aspcud-basic) S 6923 6924 32685 0 -1 4202496 762 30877 0 0 0 0 293 22 20 0 1 0 37062669 9433088 365 18446744073709551615 4194304 5129932 140736997460464 140736997459120 139729693934686 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6924/statm: 2303 365 303 229 0 63 0
[pid=6941] ppid=6924 vsize=154792 CPUtime=3.09
/proc/6941/stat : 6941 (gringo) R 6924 6924 32685 0 -1 4202496 37507 0 0 0 292 17 0 0 20 0 1 0 37062988 158507008 32838 18446744073709551615 4194304 6531320 140733306400032 140733306396376 4360311 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/6941/statm: 38698 32838 282 571 0 38119 0
Current children cumulated CPU time (s) 6.24
Current children cumulated vsize (KiB) 164004

[startup+12.7004 s]
/proc/loadavg: 0.98 0.95 0.79 2/64 6943
/proc/meminfo: memFree=235368/1022884 swapFree=0/0
[pid=6924] ppid=6923 vsize=9212 CPUtime=9.63
/proc/6924/stat : 6924 (aspcud-basic) S 6923 6924 32685 0 -1 4202496 801 127167 0 0 0 0 885 78 20 0 1 0 37062669 9433088 365 18446744073709551615 4194304 5129932 140736997460464 140736997458528 139729693934686 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6924/statm: 2303 365 303 229 0 63 0
[pid=6942] ppid=6924 vsize=123644 CPUtime=2.74
/proc/6942/stat : 6942 (clasp) R 6924 6924 32685 0 -1 4202496 36269 0 1 0 259 15 0 0 20 0 1 0 37063657 126611456 30337 18446744073709551615 4194304 6238623 140736288637152 140736288634176 4747481 0 0 16781316 18946 0 0 0 17 0 0 0 3 0 0
/proc/6942/statm: 30911 30337 263 500 0 30408 0
[pid=6943] ppid=6924 vsize=22040 CPUtime=0.02
/proc/6943/stat : 6943 (parse.py) S 6924 6924 32685 0 -1 4202496 1307 0 13 0 2 0 0 0 20 0 1 0 37063657 22568960 1128 18446744073709551615 4194304 6642060 140737297972592 140737297970952 139833782335264 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/6943/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.39
Current children cumulated vsize (KiB) 154896

[startup+25.5003 s]
/proc/loadavg: 0.99 0.95 0.79 2/65 6948
/proc/meminfo: memFree=234864/1022884 swapFree=0/0
[pid=6924] ppid=6923 vsize=9212 CPUtime=9.63
/proc/6924/stat : 6924 (aspcud-basic) S 6923 6924 32685 0 -1 4202496 801 127167 0 0 0 0 885 78 20 0 1 0 37062669 9433088 365 18446744073709551615 4194304 5129932 140736997460464 140736997458528 139729693934686 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6924/statm: 2303 365 303 229 0 63 0
[pid=6942] ppid=6924 vsize=123644 CPUtime=15.39
/proc/6942/stat : 6942 (clasp) R 6924 6924 32685 0 -1 4202496 36316 0 1 0 1524 15 0 0 20 0 1 0 37063657 126611456 30384 18446744073709551615 4194304 6238623 140736288637152 140736288634176 4409931 0 0 16781316 18946 0 0 0 17 0 0 0 3 0 0
/proc/6942/statm: 30911 30384 264 500 0 30408 0
[pid=6943] ppid=6924 vsize=22040 CPUtime=0.02
/proc/6943/stat : 6943 (parse.py) S 6924 6924 32685 0 -1 4202496 1307 0 13 0 2 0 0 0 20 0 1 0 37063657 22568960 1128 18446744073709551615 4194304 6642060 140737297972592 140737297970952 139833782335264 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/6943/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.04
Current children cumulated vsize (KiB) 154896

[startup+51.1003 s]
/proc/loadavg: 1.25 1.02 0.82 2/64 7191
/proc/meminfo: memFree=10120/1022884 swapFree=0/0
[pid=6924] ppid=6923 vsize=9212 CPUtime=9.63
/proc/6924/stat : 6924 (aspcud-basic) S 6923 6924 32685 0 -1 4202496 801 127167 0 0 0 0 885 78 20 0 1 0 37062669 9433088 365 18446744073709551615 4194304 5129932 140736997460464 140736997458528 139729693934686 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6924/statm: 2303 365 303 229 0 63 0
[pid=6942] ppid=6924 vsize=177500 CPUtime=35.84
/proc/6942/stat : 6942 (clasp) R 6924 6924 32685 0 -1 4202496 50011 0 1 0 3561 23 0 0 20 0 1 0 37063657 181760000 44079 18446744073709551615 4194304 6238623 140736288637152 140736288633704 4331909 0 0 16781316 18946 0 0 0 17 0 0 0 3 0 0
/proc/6942/statm: 44375 44079 264 500 0 43872 0
[pid=6943] ppid=6924 vsize=22040 CPUtime=0.02
/proc/6943/stat : 6943 (parse.py) S 6924 6924 32685 0 -1 4202496 1307 0 13 0 2 0 0 0 20 0 1 0 37063657 22568960 1128 18446744073709551615 4194304 6642060 140737297972592 140737297970952 139833782335264 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/6943/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 45.49
Current children cumulated vsize (KiB) 208752

[startup+102.3 s]
/proc/loadavg: 1.10 1.01 0.82 2/64 7191
/proc/meminfo: memFree=9284/1022884 swapFree=0/0
[pid=6924] ppid=6923 vsize=9212 CPUtime=9.63
/proc/6924/stat : 6924 (aspcud-basic) S 6923 6924 32685 0 -1 4202496 801 127167 0 0 0 0 885 78 20 0 1 0 37062669 9433088 365 18446744073709551615 4194304 5129932 140736997460464 140736997458528 139729693934686 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6924/statm: 2303 365 303 229 0 63 0
[pid=6942] ppid=6924 vsize=298788 CPUtime=86.69
/proc/6942/stat : 6942 (clasp) R 6924 6924 32685 0 -1 4202496 80273 0 1 0 8635 34 0 0 20 0 1 0 37063657 305958912 74340 18446744073709551615 4194304 6238623 140736288637152 140736288633704 4636176 0 0 16781316 18946 0 0 0 17 0 0 0 3 0 0
/proc/6942/statm: 74697 74340 264 500 0 74194 0
[pid=6943] ppid=6924 vsize=22040 CPUtime=0.02
/proc/6943/stat : 6943 (parse.py) S 6924 6924 32685 0 -1 4202496 1307 0 13 0 2 0 0 0 20 0 1 0 37063657 22568960 1128 18446744073709551615 4194304 6642060 140737297972592 140737297970952 139833782335264 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/6943/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 96.34
Current children cumulated vsize (KiB) 330040



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+156.303 s]
/proc/loadavg: 1.04 1.00 0.83 2/64 7191
/proc/meminfo: memFree=10284/1022884 swapFree=0/0
[pid=6924] ppid=6923 vsize=9212 CPUtime=9.63
/proc/6924/stat : 6924 (aspcud-basic) S 6923 6924 32685 0 -1 4202496 801 127167 0 0 0 0 885 78 20 0 1 0 37062669 9433088 365 18446744073709551615 4194304 5129932 140736997460464 140736997458528 139729693934686 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6924/statm: 2303 365 303 229 0 63 0
[pid=6942] ppid=6924 vsize=301500 CPUtime=140.4
/proc/6942/stat : 6942 (clasp) R 6924 6924 32685 0 -1 4202496 80943 0 1 0 14006 34 0 0 20 0 1 0 37063657 308736000 75010 18446744073709551615 4194304 6238623 140736288637152 140736288633704 4331904 0 0 16781316 18946 0 0 0 17 0 0 0 3 0 0
/proc/6942/statm: 75375 75010 264 500 0 74872 0
[pid=6943] ppid=6924 vsize=22040 CPUtime=0.02
/proc/6943/stat : 6943 (parse.py) S 6924 6924 32685 0 -1 4202496 1307 0 13 0 2 0 0 0 20 0 1 0 37063657 22568960 1128 18446744073709551615 4194304 6642060 140737297972592 140737297970952 139833782335264 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/6943/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 332752

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+156.416 s]
/proc/loadavg: 1.04 1.00 0.83 2/64 7191
/proc/meminfo: memFree=10284/1022884 swapFree=0/0
[pid=6924] ppid=6923 vsize=9212 CPUtime=150.11
/proc/6924/stat : 6924 (aspcud-basic) S 6923 6924 32685 0 -1 4202496 838 209501 0 14 0 0 14894 117 20 0 1 0 37062669 9433088 365 18446744073709551615 4194304 5129932 140736997460464 140736997458016 139729693934686 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6924/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 150.11
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 156.445
CPU time (s): 150.141
CPU user time (s): 148.953
CPU system time (s): 1.18807
CPU usage (%): 95.9707
Max. virtual memory (cumulated for all children) (KiB): 426168

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 148.953
system time used= 1.18807
maximum resident set size= 350080
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 210571
page faults= 15
swaps= 0
block input operations= 44960
block output operations= 42992
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 112
involuntary context switches= 6821

runsolver used 0.144009 second user time and 0.732045 second system time

The end