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/6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/real/6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/dist-upgrade/real/6b0d1da0-c730-11df-a7c5-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

[startup+0 s]
/proc/loadavg: 1.09 1.05 1.01 2/59 29564
/proc/meminfo: memFree=340308/1022884 swapFree=0/0
[pid=29564] ppid=29563 vsize=3152 CPUtime=0
/proc/29564/stat : 29564 (runsolver) R 29563 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 117955629 3227648 32 18446744073709551615 134512640 134586868 4290858080 4290856128 4151247920 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/29564/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.196031 s]
/proc/loadavg: 1.09 1.05 1.01 2/59 29564
/proc/meminfo: memFree=340308/1022884 swapFree=0/0
[pid=29564] ppid=29563 vsize=9212 CPUtime=0.02
/proc/29564/stat : 29564 (aspcud-full) S 29563 29564 1733 0 -1 4202496 739 3617 0 0 0 0 2 0 20 0 1 0 117955629 9433088 365 18446744073709551615 4194304 5129932 140737361335840 140737361334496 139635329868894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29564/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.20027 s]
/proc/loadavg: 1.09 1.05 1.01 2/59 29564
/proc/meminfo: memFree=340308/1022884 swapFree=0/0
[pid=29564] ppid=29563 vsize=9212 CPUtime=0.02
/proc/29564/stat : 29564 (aspcud-full) S 29563 29564 1733 0 -1 4202496 739 3617 0 0 0 0 2 0 20 0 1 0 117955629 9433088 365 18446744073709551615 4194304 5129932 140737361335840 140737361334496 139635329868894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29564/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300262 s]
/proc/loadavg: 1.09 1.05 1.01 2/59 29564
/proc/meminfo: memFree=340308/1022884 swapFree=0/0
[pid=29564] ppid=29563 vsize=9212 CPUtime=0.02
/proc/29564/stat : 29564 (aspcud-full) S 29563 29564 1733 0 -1 4202496 739 3617 0 0 0 0 2 0 20 0 1 0 117955629 9433088 365 18446744073709551615 4194304 5129932 140737361335840 140737361334496 139635329868894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29564/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700237 s]
/proc/loadavg: 1.09 1.05 1.01 2/59 29564
/proc/meminfo: memFree=340308/1022884 swapFree=0/0
[pid=29564] ppid=29563 vsize=9212 CPUtime=0.02
/proc/29564/stat : 29564 (aspcud-full) S 29563 29564 1733 0 -1 4202496 739 3617 0 0 0 0 2 0 20 0 1 0 117955629 9433088 365 18446744073709551615 4194304 5129932 140737361335840 140737361334496 139635329868894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29564/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50033 s]
/proc/loadavg: 1.09 1.05 1.01 2/61 29580
/proc/meminfo: memFree=302688/1022884 swapFree=0/0
[pid=29564] ppid=29563 vsize=9212 CPUtime=0.02
/proc/29564/stat : 29564 (aspcud-full) S 29563 29564 1733 0 -1 4202496 739 3617 0 0 0 0 2 0 20 0 1 0 117955629 9433088 365 18446744073709551615 4194304 5129932 140737361335840 140737361334496 139635329868894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29564/statm: 2303 365 303 229 0 63 0
[pid=29580] ppid=29564 vsize=54624 CPUtime=1.37
/proc/29580/stat : 29580 (cudf2lp) R 29564 29564 1733 0 -1 4202496 15333 0 0 0 130 7 0 0 20 0 1 0 117955632 55934976 11934 18446744073709551615 4194304 5690517 140734829689664 140734829687304 4970346 0 0 16781316 0 0 0 0 17 0 0 0 8 0 0
/proc/29580/statm: 13656 11934 160 366 0 13287 0
Current children cumulated CPU time (s) 1.39
Current children cumulated vsize (KiB) 63836

[startup+3.10033 s]
/proc/loadavg: 1.08 1.05 1.01 2/61 29580
/proc/meminfo: memFree=247608/1022884 swapFree=0/0
[pid=29564] ppid=29563 vsize=9212 CPUtime=2.92
/proc/29564/stat : 29564 (aspcud-full) S 29563 29564 1733 0 -1 4202496 764 30337 0 0 0 0 273 19 20 0 1 0 117955629 9433088 365 18446744073709551615 4194304 5129932 140737361335840 140737361334496 139635329868894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29564/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 2.92
Current children cumulated vsize (KiB) 9212

[startup+6.30026 s]
/proc/loadavg: 1.08 1.05 1.01 2/61 29581
/proc/meminfo: memFree=205540/1022884 swapFree=0/0
[pid=29564] ppid=29563 vsize=9212 CPUtime=2.92
/proc/29564/stat : 29564 (aspcud-full) S 29563 29564 1733 0 -1 4202496 764 30337 0 0 0 0 273 19 20 0 1 0 117955629 9433088 365 18446744073709551615 4194304 5129932 140737361335840 140737361334496 139635329868894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29564/statm: 2303 365 303 229 0 63 0
[pid=29581] ppid=29564 vsize=243068 CPUtime=3.21
/proc/29581/stat : 29581 (gringo) R 29564 29564 1733 0 -1 4202496 57461 0 0 0 301 20 0 0 20 0 1 0 117955934 248901632 48214 18446744073709551615 4194304 6531320 140735926266240 140735926262520 4596844 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/29581/statm: 60767 48214 282 571 0 60188 0
Current children cumulated CPU time (s) 6.13
Current children cumulated vsize (KiB) 252280

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

[startup+6.40033 s]
/proc/loadavg: 1.08 1.05 1.01 2/61 29581
/proc/meminfo: memFree=205540/1022884 swapFree=0/0
[pid=29564] ppid=29563 vsize=9212 CPUtime=2.92
/proc/29564/stat : 29564 (aspcud-full) S 29563 29564 1733 0 -1 4202496 764 30337 0 0 0 0 273 19 20 0 1 0 117955629 9433088 365 18446744073709551615 4194304 5129932 140737361335840 140737361334496 139635329868894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29564/statm: 2303 365 303 229 0 63 0
[pid=29581] ppid=29564 vsize=262500 CPUtime=3.31
/proc/29581/stat : 29581 (gringo) R 29564 29564 1733 0 -1 4202496 61778 0 0 0 310 21 0 0 20 0 1 0 117955934 268800000 52531 18446744073709551615 4194304 6531320 140735926266240 140735926262856 5101296 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/29581/statm: 65625 52531 282 571 0 65046 0
Current children cumulated CPU time (s) 6.23
Current children cumulated vsize (KiB) 271712

[startup+7.20021 s]
/proc/loadavg: 1.08 1.05 1.01 2/61 29581
/proc/meminfo: memFree=75456/1022884 swapFree=0/0
[pid=29564] ppid=29563 vsize=9212 CPUtime=6.86
/proc/29564/stat : 29564 (aspcud-full) S 29563 29564 1733 0 -1 4202496 804 99836 0 0 0 0 638 48 20 0 1 0 117955629 9433088 365 18446744073709551615 4194304 5129932 140737361335840 140737361333904 139635329868894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29564/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 6.86
Current children cumulated vsize (KiB) 9212

[startup+7.60022 s]
/proc/loadavg: 1.08 1.05 1.01 2/61 29581
/proc/meminfo: memFree=75456/1022884 swapFree=0/0
[pid=29564] ppid=29563 vsize=9212 CPUtime=6.86
/proc/29564/stat : 29564 (aspcud-full) S 29563 29564 1733 0 -1 4202496 804 99836 0 0 0 0 638 48 20 0 1 0 117955629 9433088 365 18446744073709551615 4194304 5129932 140737361335840 140737361333904 139635329868894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29564/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 6.86
Current children cumulated vsize (KiB) 9212

[startup+7.80327 s]
/proc/loadavg: 1.08 1.05 1.01 2/62 29583
/proc/meminfo: memFree=219288/1022884 swapFree=0/0
[pid=29564] ppid=29563 vsize=9212 CPUtime=6.86
/proc/29564/stat : 29564 (aspcud-full) S 29563 29564 1733 0 -1 4202496 804 99836 0 0 0 0 638 48 20 0 1 0 117955629 9433088 365 18446744073709551615 4194304 5129932 140737361335840 140737361333904 139635329868894 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/29564/statm: 2303 365 303 229 0 63 0
[pid=29582] ppid=29564 vsize=81200 CPUtime=0.76
/proc/29582/stat : 29582 (clasp) R 29564 29564 1733 0 -1 4202496 23810 0 0 0 70 6 0 0 20 0 1 0 117956331 83148800 19838 18446744073709551615 4194304 6238623 140734733431936 140734733428960 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/29582/statm: 20300 19838 264 500 0 19797 0
[pid=29583] ppid=29564 vsize=22040 CPUtime=0
/proc/29583/stat : 29583 (parse.py) S 29564 29564 1733 0 -1 4202496 1321 0 0 0 0 0 0 0 20 0 1 0 117956331 22568960 1129 18446744073709551615 4194304 6642060 140733684605744 140733684604104 140397199148832 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/29583/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 7.62
Current children cumulated vsize (KiB) 112452

Child status: 0
Real time (s): 7.84123
CPU time (s): 7.68848
CPU user time (s): 7.11244
CPU system time (s): 0.576036
CPU usage (%): 98.052
Max. virtual memory (cumulated for all children) (KiB): 307608

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.11244
system time used= 0.576036
maximum resident set size= 240992
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 126076
page faults= 0
swaps= 0
block input operations= 43848
block output operations= 34008
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 78
involuntary context switches= 912

runsolver used 0.004 second user time and 0.048003 second system time

The end