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/upgrade/difficult/rand752.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/difficult/rand752.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/dist-upgrade/upgrade/difficult/rand752.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.34 1.13 1.08 2/64 12586
/proc/meminfo: memFree=280144/1022884 swapFree=0/0
[pid=12586] ppid=12585 vsize=3152 CPUtime=0
/proc/12586/stat : 12586 (runsolver) R 12585 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 117970216 3227648 32 18446744073709551615 134512640 134586868 4291680704 4291678752 4151276592 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/12586/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.205616 s]
/proc/loadavg: 1.34 1.13 1.08 2/64 12586
/proc/meminfo: memFree=280144/1022884 swapFree=0/0
[pid=12586] ppid=12585 vsize=9212 CPUtime=0.03
/proc/12586/stat : 12586 (aspcud-full) S 12585 12586 1745 0 -1 4202496 733 3621 0 0 0 0 3 0 20 0 1 0 117970216 9433088 365 18446744073709551615 4194304 5129932 140733999693376 140733999692032 140284389880926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12586/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300279 s]
/proc/loadavg: 1.34 1.13 1.08 2/64 12586
/proc/meminfo: memFree=280144/1022884 swapFree=0/0
[pid=12586] ppid=12585 vsize=9212 CPUtime=0.03
/proc/12586/stat : 12586 (aspcud-full) S 12585 12586 1745 0 -1 4202496 733 3621 0 0 0 0 3 0 20 0 1 0 117970216 9433088 365 18446744073709551615 4194304 5129932 140733999693376 140733999692032 140284389880926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12586/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.400268 s]
/proc/loadavg: 1.34 1.13 1.08 2/64 12586
/proc/meminfo: memFree=280144/1022884 swapFree=0/0
[pid=12586] ppid=12585 vsize=9212 CPUtime=0.03
/proc/12586/stat : 12586 (aspcud-full) S 12585 12586 1745 0 -1 4202496 733 3621 0 0 0 0 3 0 20 0 1 0 117970216 9433088 365 18446744073709551615 4194304 5129932 140733999693376 140733999692032 140284389880926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12586/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700201 s]
/proc/loadavg: 1.34 1.13 1.08 2/64 12586
/proc/meminfo: memFree=280144/1022884 swapFree=0/0
[pid=12586] ppid=12585 vsize=9212 CPUtime=0.03
/proc/12586/stat : 12586 (aspcud-full) S 12585 12586 1745 0 -1 4202496 733 3621 0 0 0 0 3 0 20 0 1 0 117970216 9433088 365 18446744073709551615 4194304 5129932 140733999693376 140733999692032 140284389880926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12586/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50025 s]
/proc/loadavg: 1.31 1.13 1.08 2/66 12602
/proc/meminfo: memFree=217872/1022884 swapFree=0/0
[pid=12586] ppid=12585 vsize=9212 CPUtime=0.03
/proc/12586/stat : 12586 (aspcud-full) S 12585 12586 1745 0 -1 4202496 733 3621 0 0 0 0 3 0 20 0 1 0 117970216 9433088 365 18446744073709551615 4194304 5129932 140733999693376 140733999692032 140284389880926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12586/statm: 2303 365 303 229 0 63 0
[pid=12602] ppid=12586 vsize=53756 CPUtime=1.41
/proc/12602/stat : 12602 (cudf2lp) R 12586 12586 1745 0 -1 4202496 15733 0 0 0 131 10 0 0 20 0 1 0 117970218 55046144 12335 18446744073709551615 4194304 5690517 140734863028128 140734863025768 4247026 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/12602/statm: 13439 12335 160 366 0 13070 0
Current children cumulated CPU time (s) 1.44
Current children cumulated vsize (KiB) 62968

[startup+3.10026 s]
/proc/loadavg: 1.31 1.13 1.08 2/66 12602
/proc/meminfo: memFree=162940/1022884 swapFree=0/0
[pid=12586] ppid=12585 vsize=9212 CPUtime=0.03
/proc/12586/stat : 12586 (aspcud-full) S 12585 12586 1745 0 -1 4202496 733 3621 0 0 0 0 3 0 20 0 1 0 117970216 9433088 365 18446744073709551615 4194304 5129932 140733999693376 140733999692032 140284389880926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12586/statm: 2303 365 303 229 0 63 0
[pid=12602] ppid=12586 vsize=122588 CPUtime=3
/proc/12602/stat : 12602 (cudf2lp) R 12586 12586 1745 0 -1 4202496 41275 0 0 0 282 18 0 0 20 0 1 0 117970218 125530112 30319 18446744073709551615 4194304 5690517 140734863028128 140734863025304 4267811 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/12602/statm: 30647 30319 174 366 0 30278 0
Current children cumulated CPU time (s) 3.03
Current children cumulated vsize (KiB) 131800

[startup+6.30024 s]
/proc/loadavg: 1.31 1.13 1.08 2/66 12603
/proc/meminfo: memFree=131816/1022884 swapFree=0/0
[pid=12586] ppid=12585 vsize=9212 CPUtime=3.55
/proc/12586/stat : 12586 (aspcud-full) S 12585 12586 1745 0 -1 4202496 757 44898 0 0 0 0 330 25 20 0 1 0 117970216 9433088 365 18446744073709551615 4194304 5129932 140733999693376 140733999692032 140284389880926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12586/statm: 2303 365 303 229 0 63 0
[pid=12603] ppid=12586 vsize=193260 CPUtime=2.66
/proc/12603/stat : 12603 (gringo) R 12586 12586 1745 0 -1 4202496 49246 0 0 0 248 18 0 0 20 0 1 0 117970577 197898240 38942 18446744073709551615 4194304 6531320 140734674396336 140734674392264 4597226 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/12603/statm: 48315 38942 280 571 0 47736 0
Current children cumulated CPU time (s) 6.21
Current children cumulated vsize (KiB) 202472

[startup+12.7003 s]
/proc/loadavg: 1.27 1.12 1.08 2/67 12605
/proc/meminfo: memFree=317152/1022884 swapFree=0/0
[pid=12586] ppid=12585 vsize=9212 CPUtime=9.94
/proc/12586/stat : 12586 (aspcud-full) S 12585 12586 1745 0 -1 4202496 794 180606 0 0 0 0 913 81 20 0 1 0 117970216 9433088 365 18446744073709551615 4194304 5129932 140733999693376 140733999691440 140284389880926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12586/statm: 2303 365 303 229 0 63 0
[pid=12604] ppid=12586 vsize=161868 CPUtime=2.39
/proc/12604/stat : 12604 (clasp) R 12586 12586 1745 0 -1 4202496 48107 0 1 0 224 15 0 0 20 0 1 0 117971239 165752832 39604 18446744073709551615 4194304 6238623 140736850504080 140736850501104 4676699 0 0 16781316 18946 0 0 0 17 0 0 0 3 0 0
/proc/12604/statm: 40467 39604 263 500 0 39964 0
[pid=12605] ppid=12586 vsize=22040 CPUtime=0.01
/proc/12605/stat : 12605 (parse.py) S 12586 12586 1745 0 -1 4202496 1306 0 13 0 0 1 0 0 20 0 1 0 117971239 22568960 1129 18446744073709551615 4194304 6642060 140733311532752 140733311531112 140575303366432 0 0 16777220 20994 0 0 0 17 0 0 0 15 0 0
/proc/12605/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 12.34
Current children cumulated vsize (KiB) 193120

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

[startup+12.9003 s]
/proc/loadavg: 1.27 1.12 1.08 2/67 12605
/proc/meminfo: memFree=317152/1022884 swapFree=0/0
[pid=12586] ppid=12585 vsize=9212 CPUtime=9.94
/proc/12586/stat : 12586 (aspcud-full) S 12585 12586 1745 0 -1 4202496 794 180606 0 0 0 0 913 81 20 0 1 0 117970216 9433088 365 18446744073709551615 4194304 5129932 140733999693376 140733999691440 140284389880926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12586/statm: 2303 365 303 229 0 63 0
[pid=12604] ppid=12586 vsize=161868 CPUtime=2.59
/proc/12604/stat : 12604 (clasp) R 12586 12586 1745 0 -1 4202496 48108 0 1 0 244 15 0 0 20 0 1 0 117971239 165752832 39605 18446744073709551615 4194304 6238623 140736850504080 140736850501104 4423422 0 0 16781316 18946 0 0 0 17 0 0 0 3 0 0
/proc/12604/statm: 40467 39605 264 500 0 39964 0
[pid=12605] ppid=12586 vsize=22040 CPUtime=0.01
/proc/12605/stat : 12605 (parse.py) S 12586 12586 1745 0 -1 4202496 1306 0 13 0 0 1 0 0 20 0 1 0 117971239 22568960 1129 18446744073709551615 4194304 6642060 140733311532752 140733311531112 140575303366432 0 0 16777220 20994 0 0 0 17 0 0 0 15 0 0
/proc/12605/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 12.54
Current children cumulated vsize (KiB) 193120

[startup+13.3003 s]
/proc/loadavg: 1.27 1.12 1.08 2/67 12605
/proc/meminfo: memFree=317152/1022884 swapFree=0/0
[pid=12586] ppid=12585 vsize=9212 CPUtime=9.94
/proc/12586/stat : 12586 (aspcud-full) S 12585 12586 1745 0 -1 4202496 794 180606 0 0 0 0 913 81 20 0 1 0 117970216 9433088 365 18446744073709551615 4194304 5129932 140733999693376 140733999691440 140284389880926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12586/statm: 2303 365 303 229 0 63 0
[pid=12604] ppid=12586 vsize=161868 CPUtime=2.99
/proc/12604/stat : 12604 (clasp) R 12586 12586 1745 0 -1 4202496 48108 0 1 0 284 15 0 0 20 0 1 0 117971239 165752832 39605 18446744073709551615 4194304 6238623 140736850504080 140736850501104 4371507 0 0 16781316 18946 0 0 0 17 0 0 0 3 0 0
/proc/12604/statm: 40467 39605 264 500 0 39964 0
[pid=12605] ppid=12586 vsize=22040 CPUtime=0.01
/proc/12605/stat : 12605 (parse.py) S 12586 12586 1745 0 -1 4202496 1306 0 13 0 0 1 0 0 20 0 1 0 117971239 22568960 1129 18446744073709551615 4194304 6642060 140733311532752 140733311531112 140575303366432 0 0 16777220 20994 0 0 0 17 0 0 0 15 0 0
/proc/12605/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 12.94
Current children cumulated vsize (KiB) 193120

[startup+13.5004 s]
/proc/loadavg: 1.27 1.12 1.08 2/67 12605
/proc/meminfo: memFree=317152/1022884 swapFree=0/0
[pid=12586] ppid=12585 vsize=9212 CPUtime=13.11
/proc/12586/stat : 12586 (aspcud-full) S 12585 12586 1745 0 -1 4202496 830 230056 0 14 0 0 1210 101 20 0 1 0 117970216 9433088 365 18446744073709551615 4194304 5129932 140733999693376 140733999690928 140284389880926 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12586/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 13.11
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 13.5576
CPU time (s): 13.1408
CPU user time (s): 12.1088
CPU system time (s): 1.03206
CPU usage (%): 96.9259
Max. virtual memory (cumulated for all children) (KiB): 587196

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 12.1088
system time used= 1.03206
maximum resident set size= 468828
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 231120
page faults= 15
swaps= 0
block input operations= 69960
block output operations= 65384
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 93
involuntary context switches= 2020

runsolver used 0.012 second user time and 0.060003 second system time

The end