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/caefdef6-3477-11e0-84ef-00163e3d3b7c.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/real/caefdef6-3477-11e0-84ef-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/dist-upgrade/real/caefdef6-3477-11e0-84ef-00163e3d3b7c.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.06 1.05 1.06 2/64 11732
/proc/meminfo: memFree=549588/1022884 swapFree=0/0
[pid=11732] ppid=11731 vsize=9204 CPUtime=0
/proc/11732/stat : 11732 (aspcud-full) S 11731 11732 1745 0 -1 4202496 430 0 0 0 0 0 0 0 20 0 1 0 117945627 9424896 331 18446744073709551615 4194304 5129932 140733291139216 140733291136680 139926038673184 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/11732/statm: 2301 331 272 229 0 61 0

[startup+0.208421 s]
/proc/loadavg: 1.06 1.05 1.06 2/64 11732
/proc/meminfo: memFree=549588/1022884 swapFree=0/0
[pid=11732] ppid=11731 vsize=9212 CPUtime=0.05
/proc/11732/stat : 11732 (aspcud-full) S 11731 11732 1745 0 -1 4202496 731 3616 0 0 0 0 4 1 20 0 1 0 117945627 9433088 364 18446744073709551615 4194304 5129932 140733291139216 140733291137872 139926038529118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11732/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300362 s]
/proc/loadavg: 1.06 1.05 1.06 2/64 11732
/proc/meminfo: memFree=549588/1022884 swapFree=0/0
[pid=11732] ppid=11731 vsize=9212 CPUtime=0.05
/proc/11732/stat : 11732 (aspcud-full) S 11731 11732 1745 0 -1 4202496 731 3616 0 0 0 0 4 1 20 0 1 0 117945627 9433088 364 18446744073709551615 4194304 5129932 140733291139216 140733291137872 139926038529118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11732/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.400322 s]
/proc/loadavg: 1.06 1.05 1.06 2/64 11732
/proc/meminfo: memFree=549588/1022884 swapFree=0/0
[pid=11732] ppid=11731 vsize=9212 CPUtime=0.05
/proc/11732/stat : 11732 (aspcud-full) S 11731 11732 1745 0 -1 4202496 731 3616 0 0 0 0 4 1 20 0 1 0 117945627 9433088 364 18446744073709551615 4194304 5129932 140733291139216 140733291137872 139926038529118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11732/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700223 s]
/proc/loadavg: 1.06 1.05 1.06 2/64 11732
/proc/meminfo: memFree=549588/1022884 swapFree=0/0
[pid=11732] ppid=11731 vsize=9212 CPUtime=0.05
/proc/11732/stat : 11732 (aspcud-full) S 11731 11732 1745 0 -1 4202496 731 3616 0 0 0 0 4 1 20 0 1 0 117945627 9433088 364 18446744073709551615 4194304 5129932 140733291139216 140733291137872 139926038529118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11732/statm: 2303 364 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: 1.06 1.05 1.06 2/66 11748
/proc/meminfo: memFree=511620/1022884 swapFree=0/0
[pid=11732] ppid=11731 vsize=9212 CPUtime=0.05
/proc/11732/stat : 11732 (aspcud-full) S 11731 11732 1745 0 -1 4202496 731 3616 0 0 0 0 4 1 20 0 1 0 117945627 9433088 364 18446744073709551615 4194304 5129932 140733291139216 140733291137872 139926038529118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11732/statm: 2303 364 303 229 0 63 0
[pid=11748] ppid=11732 vsize=60256 CPUtime=1.43
/proc/11748/stat : 11748 (cudf2lp) R 11732 11732 1745 0 -1 4202496 14863 0 0 0 134 9 0 0 20 0 1 0 117945630 61702144 13130 18446744073709551615 4194304 5690517 140734492695264 140734492691464 4970346 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/11748/statm: 15064 13130 160 366 0 14695 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 69468

[startup+3.10031 s]
/proc/loadavg: 1.06 1.05 1.06 2/66 11749
/proc/meminfo: memFree=528484/1022884 swapFree=0/0
[pid=11732] ppid=11731 vsize=9212 CPUtime=2.24
/proc/11732/stat : 11732 (aspcud-full) S 11731 11732 1745 0 -1 4202496 756 23311 0 0 0 0 207 17 20 0 1 0 117945627 9433088 364 18446744073709551615 4194304 5129932 140733291139216 140733291137872 139926038529118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11732/statm: 2303 364 303 229 0 63 0
[pid=11749] ppid=11732 vsize=28840 CPUtime=0.82
/proc/11749/stat : 11749 (gringo) R 11732 11732 1745 0 -1 4202496 7387 0 0 0 78 4 0 0 20 0 1 0 117945853 29532160 6276 18446744073709551615 4194304 6531320 140734674990224 140734674987208 4593512 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/11749/statm: 7210 6276 276 571 0 6631 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 38052

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

[startup+3.30034 s]
/proc/loadavg: 1.06 1.05 1.06 2/66 11749
/proc/meminfo: memFree=528484/1022884 swapFree=0/0
[pid=11732] ppid=11731 vsize=9212 CPUtime=2.24
/proc/11732/stat : 11732 (aspcud-full) S 11731 11732 1745 0 -1 4202496 756 23311 0 0 0 0 207 17 20 0 1 0 117945627 9433088 364 18446744073709551615 4194304 5129932 140733291139216 140733291137872 139926038529118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11732/statm: 2303 364 303 229 0 63 0
[pid=11749] ppid=11732 vsize=47132 CPUtime=1.02
/proc/11749/stat : 11749 (gringo) R 11732 11732 1745 0 -1 4202496 11890 0 0 0 96 6 0 0 20 0 1 0 117945853 48263168 9754 18446744073709551615 4194304 6531320 140734674990224 140734674986840 5563160 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/11749/statm: 11783 9754 280 571 0 11204 0
Current children cumulated CPU time (s) 3.26
Current children cumulated vsize (KiB) 56344

[startup+4.10032 s]
/proc/loadavg: 1.06 1.05 1.06 2/66 11749
/proc/meminfo: memFree=482480/1022884 swapFree=0/0
[pid=11732] ppid=11731 vsize=9212 CPUtime=2.24
/proc/11732/stat : 11732 (aspcud-full) S 11731 11732 1745 0 -1 4202496 756 23311 0 0 0 0 207 17 20 0 1 0 117945627 9433088 364 18446744073709551615 4194304 5129932 140733291139216 140733291137872 139926038529118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11732/statm: 2303 364 303 229 0 63 0
[pid=11749] ppid=11732 vsize=113748 CPUtime=1.81
/proc/11749/stat : 11749 (gringo) R 11732 11732 1745 0 -1 4202496 26903 0 0 0 168 13 0 0 20 0 1 0 117945853 116477952 22718 18446744073709551615 4194304 6531320 140734674990224 140734674986840 4315058 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/11749/statm: 28437 22718 282 571 0 27858 0
Current children cumulated CPU time (s) 4.05
Current children cumulated vsize (KiB) 122960

[startup+4.90031 s]
/proc/loadavg: 1.06 1.05 1.06 3/67 11751
/proc/meminfo: memFree=523880/1022884 swapFree=0/0
[pid=11732] ppid=11731 vsize=9212 CPUtime=4.45
/proc/11732/stat : 11732 (aspcud-full) S 11731 11732 1745 0 -1 4202496 795 57793 0 0 0 0 409 36 20 0 1 0 117945627 9433088 364 18446744073709551615 4194304 5129932 140733291139216 140733291137280 139926038529118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11732/statm: 2303 364 303 229 0 63 0
[pid=11750] ppid=11732 vsize=45592 CPUtime=0.37
/proc/11750/stat : 11750 (clasp) R 11732 11732 1745 0 -1 4202496 13616 0 0 0 33 4 0 0 20 0 1 0 117946076 46686208 11073 18446744073709551615 4194304 6238623 140733321371488 140733321368512 4687936 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/11750/statm: 11398 11073 263 500 0 10895 0
[pid=11751] ppid=11732 vsize=22040 CPUtime=0
/proc/11751/stat : 11751 (parse.py) S 11732 11732 1745 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 117946076 22568960 1128 18446744073709551615 4194304 6642060 140737442155024 140737442153384 139678152840992 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/11751/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 4.82
Current children cumulated vsize (KiB) 76844

[startup+5.10052 s]
/proc/loadavg: 1.06 1.05 1.06 3/67 11751
/proc/meminfo: memFree=523880/1022884 swapFree=0/0
[pid=11732] ppid=11731 vsize=9212 CPUtime=4.45
/proc/11732/stat : 11732 (aspcud-full) S 11731 11732 1745 0 -1 4202496 795 57793 0 0 0 0 409 36 20 0 1 0 117945627 9433088 364 18446744073709551615 4194304 5129932 140733291139216 140733291137280 139926038529118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11732/statm: 2303 364 303 229 0 63 0
[pid=11750] ppid=11732 vsize=0 CPUtime=0.57
/proc/11750/stat : 11750 (clasp) R 11732 11732 1745 0 -1 4202500 13632 0 0 0 52 5 0 0 20 0 1 0 117946076 0 0 18446744073709551615 0 0 0 0 0 0 0 16781316 18946 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/11750/statm: 0 0 0 0 0 0 0
[pid=11751] ppid=11732 vsize=22192 CPUtime=0.01
/proc/11751/stat : 11751 (parse.py) R 11732 11732 1745 0 -1 4202496 1364 0 0 0 0 1 0 0 20 0 1 0 117946076 22724608 1173 18446744073709551615 4194304 6642060 140737442155024 140737442153144 139678152497070 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/11751/statm: 5548 1173 518 598 0 634 0
Current children cumulated CPU time (s) 5.03
Current children cumulated vsize (KiB) 31404

[startup+5.20033 s]
/proc/loadavg: 1.06 1.05 1.06 3/67 11751
/proc/meminfo: memFree=523880/1022884 swapFree=0/0
[pid=11732] ppid=11731 vsize=9212 CPUtime=5.05
/proc/11732/stat : 11732 (aspcud-full) S 11731 11732 1745 0 -1 4202496 829 72794 0 0 0 0 462 43 20 0 1 0 117945627 9433088 364 18446744073709551615 4194304 5129932 140733291139216 140733291136768 139926038529118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/11732/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 5.05
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 5.20127
CPU time (s): 5.08032
CPU user time (s): 4.63229
CPU system time (s): 0.448028
CPU usage (%): 97.6745
Max. virtual memory (cumulated for all children) (KiB): 156556

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.63229
system time used= 0.448028
maximum resident set size= 121172
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 73859
page faults= 0
swaps= 0
block input operations= 29472
block output operations= 18664
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 122
involuntary context switches= 610

runsolver used 0.016001 second user time and 0.024001 second system time

The end