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/6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/real/6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/paranoid-size/real/6b0d1da0-c730-11df-a7c5-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.83 0.91 0.75 2/60 3465
/proc/meminfo: memFree=409800/1022884 swapFree=0/0
[pid=3465] ppid=3464 vsize=3152 CPUtime=0
/proc/3465/stat : 3465 (runsolver) R 3464 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115276045 3227648 32 18446744073709551615 134512640 134586868 4293492128 4293490176 4151649328 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/3465/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.140015 s]
/proc/loadavg: 0.83 0.91 0.75 2/60 3465
/proc/meminfo: memFree=409800/1022884 swapFree=0/0
[pid=3465] ppid=3464 vsize=9212 CPUtime=0.02
/proc/3465/stat : 3465 (aspcud-basic) S 3464 3465 1750 0 -1 4202496 735 3620 0 0 0 0 2 0 20 0 1 0 115276045 9433088 365 18446744073709551615 4194304 5129932 140734435363472 140734435362128 140546458109022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3465/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200262 s]
/proc/loadavg: 0.83 0.91 0.75 2/60 3465
/proc/meminfo: memFree=409800/1022884 swapFree=0/0
[pid=3465] ppid=3464 vsize=9212 CPUtime=0.02
/proc/3465/stat : 3465 (aspcud-basic) S 3464 3465 1750 0 -1 4202496 735 3620 0 0 0 0 2 0 20 0 1 0 115276045 9433088 365 18446744073709551615 4194304 5129932 140734435363472 140734435362128 140546458109022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3465/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300243 s]
/proc/loadavg: 0.83 0.91 0.75 2/60 3465
/proc/meminfo: memFree=409800/1022884 swapFree=0/0
[pid=3465] ppid=3464 vsize=9212 CPUtime=0.02
/proc/3465/stat : 3465 (aspcud-basic) S 3464 3465 1750 0 -1 4202496 735 3620 0 0 0 0 2 0 20 0 1 0 115276045 9433088 365 18446744073709551615 4194304 5129932 140734435363472 140734435362128 140546458109022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3465/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700192 s]
/proc/loadavg: 0.83 0.91 0.75 2/60 3465
/proc/meminfo: memFree=409800/1022884 swapFree=0/0
[pid=3465] ppid=3464 vsize=9212 CPUtime=0.02
/proc/3465/stat : 3465 (aspcud-basic) S 3464 3465 1750 0 -1 4202496 735 3620 0 0 0 0 2 0 20 0 1 0 115276045 9433088 365 18446744073709551615 4194304 5129932 140734435363472 140734435362128 140546458109022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3465/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50025 s]
/proc/loadavg: 0.85 0.91 0.75 2/62 3481
/proc/meminfo: memFree=349388/1022884 swapFree=0/0
[pid=3465] ppid=3464 vsize=9212 CPUtime=0.02
/proc/3465/stat : 3465 (aspcud-basic) S 3464 3465 1750 0 -1 4202496 735 3620 0 0 0 0 2 0 20 0 1 0 115276045 9433088 365 18446744073709551615 4194304 5129932 140734435363472 140734435362128 140546458109022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3465/statm: 2303 365 303 229 0 63 0
[pid=3481] ppid=3465 vsize=72100 CPUtime=1.43
/proc/3481/stat : 3481 (cudf2lp) R 3465 3465 1750 0 -1 4202496 20577 0 0 0 134 9 0 0 20 0 1 0 115276048 73830400 17179 18446744073709551615 4194304 5690517 140735401728448 140735401725576 4326898 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/3481/statm: 18025 17179 168 366 0 17656 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 81312

[startup+3.10025 s]
/proc/loadavg: 0.85 0.91 0.75 2/62 3482
/proc/meminfo: memFree=369352/1022884 swapFree=0/0
[pid=3465] ppid=3464 vsize=9212 CPUtime=1.97
/proc/3465/stat : 3465 (aspcud-basic) S 3464 3465 1750 0 -1 4202496 760 29060 0 0 0 0 183 14 20 0 1 0 115276045 9433088 365 18446744073709551615 4194304 5129932 140734435363472 140734435362128 140546458109022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3465/statm: 2303 365 303 229 0 63 0
[pid=3482] ppid=3465 vsize=69380 CPUtime=1.08
/proc/3482/stat : 3482 (gringo) R 3465 3465 1750 0 -1 4202496 18104 0 0 0 103 5 0 0 20 0 1 0 115276247 71045120 15484 18446744073709551615 4194304 6531320 140736997397024 140736997393448 4596032 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/3482/statm: 17345 15484 281 571 0 16766 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 78592

[startup+6.3003 s]
/proc/loadavg: 0.85 0.91 0.75 2/62 3482
/proc/meminfo: memFree=89732/1022884 swapFree=0/0
[pid=3465] ppid=3464 vsize=9212 CPUtime=1.97
/proc/3465/stat : 3465 (aspcud-basic) S 3464 3465 1750 0 -1 4202496 760 29060 0 0 0 0 183 14 20 0 1 0 115276045 9433088 365 18446744073709551615 4194304 5129932 140734435363472 140734435362128 140546458109022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3465/statm: 2303 365 303 229 0 63 0
[pid=3482] ppid=3465 vsize=402864 CPUtime=4.25
/proc/3482/stat : 3482 (gringo) R 3465 3465 1750 0 -1 4202496 94433 0 0 0 398 27 0 0 20 0 1 0 115276247 412532736 85667 18446744073709551615 4194304 6531320 140736997397024 140736997394088 4357949 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/3482/statm: 100716 85667 283 571 0 100137 0
Current children cumulated CPU time (s) 6.22
Current children cumulated vsize (KiB) 412076

[startup+12.7004 s]
/proc/loadavg: 0.87 0.91 0.75 2/63 3484
/proc/meminfo: memFree=267532/1022884 swapFree=0/0
[pid=3465] ppid=3464 vsize=9212 CPUtime=7.66
/proc/3465/stat : 3465 (aspcud-basic) S 3464 3465 1750 0 -1 4202496 799 137428 0 0 0 0 706 60 20 0 1 0 115276045 9433088 365 18446744073709551615 4194304 5129932 140734435363472 140734435361536 140546458109022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3465/statm: 2303 365 303 229 0 63 0
[pid=3483] ppid=3465 vsize=140960 CPUtime=4.78
/proc/3483/stat : 3483 (clasp) R 3465 3465 1750 0 -1 4202496 41010 0 0 0 464 14 0 0 20 0 1 0 115276830 144343040 34805 18446744073709551615 4194304 6238623 140735607153776 140735607150800 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3483/statm: 35240 34805 263 500 0 34737 0
[pid=3484] ppid=3465 vsize=22040 CPUtime=0.02
/proc/3484/stat : 3484 (parse.py) S 3465 3465 1750 0 -1 4202496 1321 0 0 0 1 1 0 0 20 0 1 0 115276830 22568960 1129 18446744073709551615 4194304 6642060 140734426825392 140734426823752 140004664907552 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3484/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 12.46
Current children cumulated vsize (KiB) 172212

[startup+25.5004 s]
/proc/loadavg: 0.89 0.92 0.75 2/63 3484
/proc/meminfo: memFree=267036/1022884 swapFree=0/0
[pid=3465] ppid=3464 vsize=9212 CPUtime=7.66
/proc/3465/stat : 3465 (aspcud-basic) S 3464 3465 1750 0 -1 4202496 799 137428 0 0 0 0 706 60 20 0 1 0 115276045 9433088 365 18446744073709551615 4194304 5129932 140734435363472 140734435361536 140546458109022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3465/statm: 2303 365 303 229 0 63 0
[pid=3483] ppid=3465 vsize=140960 CPUtime=17.46
/proc/3483/stat : 3483 (clasp) R 3465 3465 1750 0 -1 4202496 41119 0 0 0 1732 14 0 0 20 0 1 0 115276830 144343040 34914 18446744073709551615 4194304 6238623 140735607153776 140735607150800 4371524 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3483/statm: 35240 34914 263 500 0 34737 0
[pid=3484] ppid=3465 vsize=22040 CPUtime=0.02
/proc/3484/stat : 3484 (parse.py) S 3465 3465 1750 0 -1 4202496 1321 0 0 0 1 1 0 0 20 0 1 0 115276830 22568960 1129 18446744073709551615 4194304 6642060 140734426825392 140734426823752 140004664907552 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3484/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 25.14
Current children cumulated vsize (KiB) 172212

[startup+51.1004 s]
/proc/loadavg: 0.93 0.92 0.76 2/64 3562
/proc/meminfo: memFree=245436/1022884 swapFree=0/0
[pid=3465] ppid=3464 vsize=9212 CPUtime=7.66
/proc/3465/stat : 3465 (aspcud-basic) S 3464 3465 1750 0 -1 4202496 799 137428 0 0 0 0 706 60 20 0 1 0 115276045 9433088 365 18446744073709551615 4194304 5129932 140734435363472 140734435361536 140546458109022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3465/statm: 2303 365 303 229 0 63 0
[pid=3483] ppid=3465 vsize=140960 CPUtime=41.57
/proc/3483/stat : 3483 (clasp) R 3465 3465 1750 0 -1 4202496 41120 0 0 0 4142 15 0 0 20 0 1 0 115276830 144343040 34915 18446744073709551615 4194304 6238623 140735607153776 140735607150800 4355569 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3483/statm: 35240 34915 264 500 0 34737 0
[pid=3484] ppid=3465 vsize=22040 CPUtime=0.02
/proc/3484/stat : 3484 (parse.py) S 3465 3465 1750 0 -1 4202496 1321 0 0 0 1 1 0 0 20 0 1 0 115276830 22568960 1129 18446744073709551615 4194304 6642060 140734426825392 140734426823752 140004664907552 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3484/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 49.25
Current children cumulated vsize (KiB) 172212

[startup+102.3 s]
/proc/loadavg: 1.10 0.97 0.78 2/63 3735
/proc/meminfo: memFree=9676/1022884 swapFree=0/0
[pid=3465] ppid=3464 vsize=9212 CPUtime=7.66
/proc/3465/stat : 3465 (aspcud-basic) S 3464 3465 1750 0 -1 4202496 799 137428 0 0 0 0 706 60 20 0 1 0 115276045 9433088 365 18446744073709551615 4194304 5129932 140734435363472 140734435361536 140546458109022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3465/statm: 2303 365 303 229 0 63 0
[pid=3483] ppid=3465 vsize=299096 CPUtime=85.47
/proc/3483/stat : 3483 (clasp) R 3465 3465 1750 0 -1 4202496 80661 0 0 0 8517 30 0 0 20 0 1 0 115276830 306274304 74455 18446744073709551615 4194304 6238623 140735607153776 140735607150328 4330400 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3483/statm: 74774 74455 264 500 0 74271 0
[pid=3484] ppid=3465 vsize=22040 CPUtime=0.02
/proc/3484/stat : 3484 (parse.py) S 3465 3465 1750 0 -1 4202496 1321 0 0 0 1 1 0 0 20 0 1 0 115276830 22568960 1129 18446744073709551615 4194304 6642060 140734426825392 140734426823752 140004664907552 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3484/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 93.15
Current children cumulated vsize (KiB) 330348



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+159.603 s]
/proc/loadavg: 1.07 0.99 0.80 2/63 3735
/proc/meminfo: memFree=10080/1022884 swapFree=0/0
[pid=3465] ppid=3464 vsize=9212 CPUtime=7.66
/proc/3465/stat : 3465 (aspcud-basic) S 3464 3465 1750 0 -1 4202496 799 137428 0 0 0 0 706 60 20 0 1 0 115276045 9433088 365 18446744073709551615 4194304 5129932 140734435363472 140734435361536 140546458109022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3465/statm: 2303 365 303 229 0 63 0
[pid=3483] ppid=3465 vsize=330144 CPUtime=142.36
/proc/3483/stat : 3483 (clasp) R 3465 3465 1750 0 -1 4202496 88436 0 0 0 14203 33 0 0 20 0 1 0 115276830 338067456 82230 18446744073709551615 4194304 6238623 140735607153776 140735607150328 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3483/statm: 82536 82230 264 500 0 82033 0
[pid=3484] ppid=3465 vsize=22040 CPUtime=0.02
/proc/3484/stat : 3484 (parse.py) S 3465 3465 1750 0 -1 4202496 1321 0 0 0 1 1 0 0 20 0 1 0 115276830 22568960 1129 18446744073709551615 4194304 6642060 140734426825392 140734426823752 140004664907552 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3484/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 150.04
Current children cumulated vsize (KiB) 361396

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+159.603 s]
/proc/loadavg: 1.07 0.99 0.80 2/63 3735
/proc/meminfo: memFree=10080/1022884 swapFree=0/0
[pid=3465] ppid=3464 vsize=9212 CPUtime=7.66
/proc/3465/stat : 3465 (aspcud-basic) S 3464 3465 1750 0 -1 4202496 799 137428 0 0 0 0 706 60 20 0 1 0 115276045 9433088 365 18446744073709551615 4194304 5129932 140734435363472 140734435361536 140546458109022 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3465/statm: 2303 365 303 229 0 63 0
[pid=3483] ppid=3465 vsize=330144 CPUtime=142.36
/proc/3483/stat : 3483 (clasp) R 3465 3465 1750 0 -1 4202496 88436 0 0 0 14203 33 0 0 20 0 1 0 115276830 338067456 82230 18446744073709551615 4194304 6238623 140735607153776 140735607150328 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3483/statm: 82536 82230 264 500 0 82033 0
[pid=3484] ppid=3465 vsize=22040 CPUtime=0.02
/proc/3484/stat : 3484 (parse.py) S 3465 3465 1750 0 -1 4202496 1321 0 0 0 1 1 0 0 20 0 1 0 115276830 22568960 1129 18446744073709551615 4194304 6642060 140734426825392 140734426823752 140004664907552 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3484/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 150.04
Current children cumulated vsize (KiB) 361396

Child status: 0
Real time (s): 159.679
CPU time (s): 150.105
CPU user time (s): 149.129
CPU system time (s): 0.976061
CPU usage (%): 94.0047
Max. virtual memory (cumulated for all children) (KiB): 473116

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.129
system time used= 0.976061
maximum resident set size= 398392
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 228337
page faults= 1
swaps= 0
block input operations= 43888
block output operations= 46600
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 91
involuntary context switches= 20020

runsolver used 0.344021 second user time and 0.628039 second system time

The end