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/dist-upgrade/real/56ae4afa-0b33-11df-8a2b-00163e1d94dc.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/real/56ae4afa-0b33-11df-8a2b-00163e1d94dc.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/dist-upgrade/real/56ae4afa-0b33-11df-8a2b-00163e1d94dc.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

[startup+0 s]
/proc/loadavg: 0.99 1.02 1.00 2/59 29339
/proc/meminfo: memFree=498804/1022884 swapFree=0/0
[pid=29339] ppid=29338 vsize=3152 CPUtime=0
/proc/29339/stat : 29339 (runsolver) R 29338 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 117947304 3227648 32 18446744073709551615 134512640 134586868 4288899072 4288897120 4151870512 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/29339/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.118468 s]
/proc/loadavg: 0.99 1.02 1.00 2/59 29339
/proc/meminfo: memFree=498804/1022884 swapFree=0/0
[pid=29339] ppid=29338 vsize=9212 CPUtime=0.03
/proc/29339/stat : 29339 (aspcud-full) S 29338 29339 1733 0 -1 4202496 732 3616 0 0 0 0 2 1 20 0 1 0 117947304 9433088 364 18446744073709551615 4194304 5129932 140734714151024 140734714149680 140464469541982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29339/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.20032 s]
/proc/loadavg: 0.99 1.02 1.00 2/59 29339
/proc/meminfo: memFree=498804/1022884 swapFree=0/0
[pid=29339] ppid=29338 vsize=9212 CPUtime=0.03
/proc/29339/stat : 29339 (aspcud-full) S 29338 29339 1733 0 -1 4202496 732 3616 0 0 0 0 2 1 20 0 1 0 117947304 9433088 364 18446744073709551615 4194304 5129932 140734714151024 140734714149680 140464469541982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29339/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300269 s]
/proc/loadavg: 0.99 1.02 1.00 2/59 29339
/proc/meminfo: memFree=498804/1022884 swapFree=0/0
[pid=29339] ppid=29338 vsize=9212 CPUtime=0.03
/proc/29339/stat : 29339 (aspcud-full) S 29338 29339 1733 0 -1 4202496 732 3616 0 0 0 0 2 1 20 0 1 0 117947304 9433088 364 18446744073709551615 4194304 5129932 140734714151024 140734714149680 140464469541982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29339/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700225 s]
/proc/loadavg: 0.99 1.02 1.00 2/59 29339
/proc/meminfo: memFree=498804/1022884 swapFree=0/0
[pid=29339] ppid=29338 vsize=9212 CPUtime=0.03
/proc/29339/stat : 29339 (aspcud-full) S 29338 29339 1733 0 -1 4202496 732 3616 0 0 0 0 2 1 20 0 1 0 117947304 9433088 364 18446744073709551615 4194304 5129932 140734714151024 140734714149680 140464469541982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29339/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 0.99 1.02 1.00 2/61 29355
/proc/meminfo: memFree=461084/1022884 swapFree=0/0
[pid=29339] ppid=29338 vsize=9212 CPUtime=0.03
/proc/29339/stat : 29339 (aspcud-full) S 29338 29339 1733 0 -1 4202496 732 3616 0 0 0 0 2 1 20 0 1 0 117947304 9433088 364 18446744073709551615 4194304 5129932 140734714151024 140734714149680 140464469541982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29339/statm: 2303 364 303 229 0 63 0
[pid=29355] ppid=29339 vsize=52524 CPUtime=1.43
/proc/29355/stat : 29355 (cudf2lp) R 29339 29339 1733 0 -1 4202496 14847 0 0 0 136 7 0 0 20 0 1 0 117947306 53784576 11449 18446744073709551615 4194304 5690517 140734974527712 140734974525352 4960693 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/29355/statm: 13131 11449 160 366 0 12762 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 61736

[startup+3.10027 s]
/proc/loadavg: 0.99 1.02 1.00 1/61 29355
/proc/meminfo: memFree=427728/1022884 swapFree=0/0
[pid=29339] ppid=29338 vsize=9212 CPUtime=0.03
/proc/29339/stat : 29339 (aspcud-full) S 29338 29339 1733 0 -1 4202496 732 3616 0 0 0 0 2 1 20 0 1 0 117947304 9433088 364 18446744073709551615 4194304 5129932 140734714151024 140734714149680 140464469541982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29339/statm: 2303 364 303 229 0 63 0
[pid=29355] ppid=29339 vsize=98748 CPUtime=3
/proc/29355/stat : 29355 (cudf2lp) R 29339 29339 1733 0 -1 4202496 34449 0 0 0 284 16 0 0 20 0 1 0 117947306 101117952 24322 18446744073709551615 4194304 5690517 140734974527712 140734974524552 4934605 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/29355/statm: 24687 24322 174 366 0 24318 0
Current children cumulated CPU time (s) 3.03
Current children cumulated vsize (KiB) 107960

[startup+6.30028 s]
/proc/loadavg: 0.99 1.02 1.00 2/61 29356
/proc/meminfo: memFree=337084/1022884 swapFree=0/0
[pid=29339] ppid=29338 vsize=9212 CPUtime=3.3
/proc/29339/stat : 29339 (aspcud-full) S 29338 29339 1733 0 -1 4202496 757 38067 0 0 0 0 310 20 20 0 1 0 117947304 9433088 364 18446744073709551615 4194304 5129932 140734714151024 140734714149680 140464469541982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29339/statm: 2303 364 303 229 0 63 0
[pid=29356] ppid=29339 vsize=219276 CPUtime=2.9
/proc/29356/stat : 29356 (gringo) R 29339 29339 1733 0 -1 4202496 54330 0 0 0 272 18 0 0 20 0 1 0 117947641 224538624 45084 18446744073709551615 4194304 6531320 140736353265264 140736353261272 4597976 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/29356/statm: 54819 45084 283 571 0 54240 0
Current children cumulated CPU time (s) 6.2
Current children cumulated vsize (KiB) 228488

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

[startup+6.40035 s]
/proc/loadavg: 0.99 1.02 1.00 2/61 29356
/proc/meminfo: memFree=337084/1022884 swapFree=0/0
[pid=29339] ppid=29338 vsize=9212 CPUtime=3.3
/proc/29339/stat : 29339 (aspcud-full) S 29338 29339 1733 0 -1 4202496 757 38067 0 0 0 0 310 20 20 0 1 0 117947304 9433088 364 18446744073709551615 4194304 5129932 140734714151024 140734714149680 140464469541982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29339/statm: 2303 364 303 229 0 63 0
[pid=29356] ppid=29339 vsize=240224 CPUtime=3
/proc/29356/stat : 29356 (gringo) R 29339 29339 1733 0 -1 4202496 58823 0 0 0 281 19 0 0 20 0 1 0 117947641 245989376 49577 18446744073709551615 4194304 6531320 140736353265264 140736353261688 4598302 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/29356/statm: 60056 49577 283 571 0 59477 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 249436

[startup+8.00028 s]
/proc/loadavg: 0.99 1.02 1.00 2/61 29356
/proc/meminfo: memFree=98384/1022884 swapFree=0/0
[pid=29339] ppid=29338 vsize=9212 CPUtime=3.3
/proc/29339/stat : 29339 (aspcud-full) S 29338 29339 1733 0 -1 4202496 757 38067 0 0 0 0 310 20 20 0 1 0 117947304 9433088 364 18446744073709551615 4194304 5129932 140734714151024 140734714149680 140464469541982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29339/statm: 2303 364 303 229 0 63 0
[pid=29356] ppid=29339 vsize=427952 CPUtime=4.58
/proc/29356/stat : 29356 (gringo) R 29339 29339 1733 0 -1 4202496 100470 0 0 0 428 30 0 0 20 0 1 0 117947641 438222848 91224 18446744073709551615 4194304 6531320 140736353265264 140736353262072 4344262 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/29356/statm: 106988 91224 284 571 0 106409 0
Current children cumulated CPU time (s) 7.88
Current children cumulated vsize (KiB) 437164

[startup+8.8002 s]
/proc/loadavg: 0.99 1.02 1.00 2/62 29358
/proc/meminfo: memFree=328148/1022884 swapFree=0/0
[pid=29339] ppid=29338 vsize=9212 CPUtime=8.17
/proc/29339/stat : 29339 (aspcud-full) S 29338 29339 1733 0 -1 4202496 796 138541 0 0 0 0 757 60 20 0 1 0 117947304 9433088 364 18446744073709551615 4194304 5129932 140734714151024 140734714149088 140464469541982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29339/statm: 2303 364 303 229 0 63 0
[pid=29357] ppid=29339 vsize=125088 CPUtime=0.5
/proc/29357/stat : 29357 (clasp) R 29339 29339 1733 0 -1 4202496 34569 0 0 0 43 7 0 0 20 0 1 0 117948131 128090112 30385 18446744073709551615 4194304 6238623 140737252499776 140737252497208 4494819 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/29357/statm: 31272 30385 214 500 0 30769 0
[pid=29358] ppid=29339 vsize=22040 CPUtime=0.01
/proc/29358/stat : 29358 (parse.py) S 29339 29339 1733 0 -1 4202496 1320 0 0 0 0 1 0 0 20 0 1 0 117948131 22568960 1129 18446744073709551615 4194304 6642060 140736498819328 140736498817688 139808311142176 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/29358/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 8.68
Current children cumulated vsize (KiB) 156340

[startup+9.20033 s]
/proc/loadavg: 0.99 1.02 1.00 2/62 29358
/proc/meminfo: memFree=328148/1022884 swapFree=0/0
[pid=29339] ppid=29338 vsize=9212 CPUtime=8.17
/proc/29339/stat : 29339 (aspcud-full) S 29338 29339 1733 0 -1 4202496 796 138541 0 0 0 0 757 60 20 0 1 0 117947304 9433088 364 18446744073709551615 4194304 5129932 140734714151024 140734714149088 140464469541982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29339/statm: 2303 364 303 229 0 63 0
[pid=29357] ppid=29339 vsize=121612 CPUtime=0.89
/proc/29357/stat : 29357 (clasp) R 29339 29339 1733 0 -1 4202496 35774 0 0 0 82 7 0 0 20 0 1 0 117948131 124530688 29842 18446744073709551615 4194304 6238623 140737252499776 140737252497472 4636266 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/29357/statm: 30403 29842 262 500 0 29900 0
[pid=29358] ppid=29339 vsize=22040 CPUtime=0.01
/proc/29358/stat : 29358 (parse.py) S 29339 29339 1733 0 -1 4202496 1320 0 0 0 0 1 0 0 20 0 1 0 117948131 22568960 1129 18446744073709551615 4194304 6642060 140736498819328 140736498817688 139808311142176 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/29358/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 9.07
Current children cumulated vsize (KiB) 152864

[startup+9.40033 s]
/proc/loadavg: 0.99 1.02 1.00 2/62 29358
/proc/meminfo: memFree=328148/1022884 swapFree=0/0
[pid=29339] ppid=29338 vsize=9212 CPUtime=8.17
/proc/29339/stat : 29339 (aspcud-full) S 29338 29339 1733 0 -1 4202496 796 138541 0 0 0 0 757 60 20 0 1 0 117947304 9433088 364 18446744073709551615 4194304 5129932 140734714151024 140734714149088 140464469541982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29339/statm: 2303 364 303 229 0 63 0
[pid=29357] ppid=29339 vsize=121612 CPUtime=1.09
/proc/29357/stat : 29357 (clasp) R 29339 29339 1733 0 -1 4202496 35776 0 0 0 102 7 0 0 20 0 1 0 117948131 124530688 29844 18446744073709551615 4194304 6238623 140737252499776 140737252496800 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/29357/statm: 30403 29844 264 500 0 29900 0
[pid=29358] ppid=29339 vsize=22040 CPUtime=0.01
/proc/29358/stat : 29358 (parse.py) S 29339 29339 1733 0 -1 4202496 1320 0 0 0 0 1 0 0 20 0 1 0 117948131 22568960 1129 18446744073709551615 4194304 6642060 140736498819328 140736498817688 139808311142176 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/29358/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 9.27
Current children cumulated vsize (KiB) 152864

[startup+9.50033 s]
/proc/loadavg: 0.99 1.02 1.00 2/62 29358
/proc/meminfo: memFree=328148/1022884 swapFree=0/0
[pid=29339] ppid=29338 vsize=9212 CPUtime=9.38
/proc/29339/stat : 29339 (aspcud-full) S 29338 29339 1733 0 -1 4202496 830 175672 0 0 0 0 866 72 20 0 1 0 117947304 9433088 364 18446744073709551615 4194304 5129932 140734714151024 140734714148576 140464469541982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29339/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 9.38
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 9.50166
CPU time (s): 9.40459
CPU user time (s): 8.66454
CPU system time (s): 0.740046
CPU usage (%): 98.9784
Max. virtual memory (cumulated for all children) (KiB): 437164

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 8.66454
system time used= 0.740046
maximum resident set size= 364896
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 176737
page faults= 0
swaps= 0
block input operations= 44272
block output operations= 48768
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 70
involuntary context switches= 1104

runsolver used 0.008 second user time and 0.044002 second system time

The end