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/easy/rand381.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/easy/rand381.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/dist-upgrade/upgrade/easy/rand381.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.08 1.05 1.06 2/64 12231
/proc/meminfo: memFree=288344/1022884 swapFree=0/0
[pid=12231] ppid=12230 vsize=9128 CPUtime=0
/proc/12231/stat : 12231 (aspcud-full) R 12230 12231 1745 0 -1 4202496 277 0 0 0 0 0 0 0 20 0 1 0 117964647 9347072 187 18446744073709551615 4194304 5129932 140736138019776 140736138019192 4387008 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/12231/statm: 2282 187 152 229 0 42 0

[startup+0.187906 s]
/proc/loadavg: 1.08 1.05 1.06 2/64 12231
/proc/meminfo: memFree=288344/1022884 swapFree=0/0
[pid=12231] ppid=12230 vsize=9212 CPUtime=0.05
/proc/12231/stat : 12231 (aspcud-full) S 12230 12231 1745 0 -1 4202496 743 3605 0 6 1 0 3 1 20 0 1 0 117964647 9433088 365 18446744073709551615 4194304 5129932 140736138019776 140736138018432 140350670632030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12231/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200261 s]
/proc/loadavg: 1.08 1.05 1.06 2/64 12231
/proc/meminfo: memFree=288344/1022884 swapFree=0/0
[pid=12231] ppid=12230 vsize=9212 CPUtime=0.05
/proc/12231/stat : 12231 (aspcud-full) S 12230 12231 1745 0 -1 4202496 743 3605 0 6 1 0 3 1 20 0 1 0 117964647 9433088 365 18446744073709551615 4194304 5129932 140736138019776 140736138018432 140350670632030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12231/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300248 s]
/proc/loadavg: 1.08 1.05 1.06 2/64 12231
/proc/meminfo: memFree=288344/1022884 swapFree=0/0
[pid=12231] ppid=12230 vsize=9212 CPUtime=0.05
/proc/12231/stat : 12231 (aspcud-full) S 12230 12231 1745 0 -1 4202496 743 3605 0 6 1 0 3 1 20 0 1 0 117964647 9433088 365 18446744073709551615 4194304 5129932 140736138019776 140736138018432 140350670632030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12231/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700194 s]
/proc/loadavg: 1.08 1.05 1.06 2/64 12231
/proc/meminfo: memFree=288344/1022884 swapFree=0/0
[pid=12231] ppid=12230 vsize=9212 CPUtime=0.05
/proc/12231/stat : 12231 (aspcud-full) S 12230 12231 1745 0 -1 4202496 743 3605 0 6 1 0 3 1 20 0 1 0 117964647 9433088 365 18446744073709551615 4194304 5129932 140736138019776 140736138018432 140350670632030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12231/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 1.08 1.05 1.06 2/66 12247
/proc/meminfo: memFree=252360/1022884 swapFree=0/0
[pid=12231] ppid=12230 vsize=9212 CPUtime=0.05
/proc/12231/stat : 12231 (aspcud-full) S 12230 12231 1745 0 -1 4202496 743 3605 0 6 1 0 3 1 20 0 1 0 117964647 9433088 365 18446744073709551615 4194304 5129932 140736138019776 140736138018432 140350670632030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12231/statm: 2303 365 303 229 0 63 0
[pid=12247] ppid=12231 vsize=51876 CPUtime=1.21
/proc/12247/stat : 12247 (cudf2lp) R 12231 12231 1745 0 -1 4202496 14442 0 1 0 114 7 0 0 20 0 1 0 117964655 53121024 11045 18446744073709551615 4194304 5690517 140733980068080 140733980064664 4951870 0 0 16781316 0 0 0 0 17 0 0 0 19 0 0
/proc/12247/statm: 12969 11045 159 366 0 12600 0
Current children cumulated CPU time (s) 1.26
Current children cumulated vsize (KiB) 61088

[startup+3.10033 s]
/proc/loadavg: 1.07 1.05 1.06 2/66 12247
/proc/meminfo: memFree=220244/1022884 swapFree=0/0
[pid=12231] ppid=12230 vsize=9212 CPUtime=0.05
/proc/12231/stat : 12231 (aspcud-full) S 12230 12231 1745 0 -1 4202496 743 3605 0 6 1 0 3 1 20 0 1 0 117964647 9433088 365 18446744073709551615 4194304 5129932 140736138019776 140736138018432 140350670632030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12231/statm: 2303 365 303 229 0 63 0
[pid=12247] ppid=12231 vsize=77028 CPUtime=2.77
/proc/12247/stat : 12247 (cudf2lp) R 12231 12231 1745 0 -1 4202496 25052 0 1 0 261 16 0 0 20 0 1 0 117964655 78876672 18990 18446744073709551615 4194304 5690517 140733980068080 140733980065448 4957039 0 0 16781316 0 0 0 0 17 0 0 0 22 0 0
/proc/12247/statm: 19257 18990 174 366 0 18888 0
Current children cumulated CPU time (s) 2.82
Current children cumulated vsize (KiB) 86240

[startup+6.30026 s]
/proc/loadavg: 1.07 1.05 1.06 3/65 12250
/proc/meminfo: memFree=168404/1022884 swapFree=0/0
[pid=12231] ppid=12230 vsize=9212 CPUtime=2.94
/proc/12231/stat : 12231 (aspcud-full) S 12230 12231 1745 0 -1 4202496 770 28659 0 7 1 0 273 20 20 0 1 0 117964647 9433088 365 18446744073709551615 4194304 5129932 140736138019776 140736138018432 140350670632030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12231/statm: 2303 365 303 229 0 63 0
[pid=12248] ppid=12231 vsize=184972 CPUtime=2.94
/proc/12248/stat : 12248 (gringo) R 12231 12231 1745 0 -1 4202496 45570 0 1 0 278 16 0 0 20 0 1 0 117964969 189411328 40389 18446744073709551615 4194304 6531320 140733545291552 140733545287976 4554912 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/12248/statm: 46243 40389 281 571 0 45664 0
Current children cumulated CPU time (s) 5.88
Current children cumulated vsize (KiB) 194184

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

[startup+6.40034 s]
/proc/loadavg: 1.07 1.05 1.06 3/65 12250
/proc/meminfo: memFree=168404/1022884 swapFree=0/0
[pid=12231] ppid=12230 vsize=9212 CPUtime=2.94
/proc/12231/stat : 12231 (aspcud-full) S 12230 12231 1745 0 -1 4202496 770 28659 0 7 1 0 273 20 20 0 1 0 117964647 9433088 365 18446744073709551615 4194304 5129932 140736138019776 140736138018432 140350670632030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12231/statm: 2303 365 303 229 0 63 0
[pid=12248] ppid=12231 vsize=200156 CPUtime=3.03
/proc/12248/stat : 12248 (gringo) R 12231 12231 1745 0 -1 4202496 48966 0 1 0 287 16 0 0 20 0 1 0 117964969 204959744 43785 18446744073709551615 4194304 6531320 140733545291552 140733545287480 5554604 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/12248/statm: 50039 43785 282 571 0 49460 0
Current children cumulated CPU time (s) 5.97
Current children cumulated vsize (KiB) 209368

[startup+7.20026 s]
/proc/loadavg: 1.06 1.05 1.06 2/66 12256
/proc/meminfo: memFree=55944/1022884 swapFree=0/0
[pid=12231] ppid=12230 vsize=9212 CPUtime=2.94
/proc/12231/stat : 12231 (aspcud-full) S 12230 12231 1745 0 -1 4202496 770 28659 0 7 1 0 273 20 20 0 1 0 117964647 9433088 365 18446744073709551615 4194304 5129932 140736138019776 140736138018432 140350670632030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12231/statm: 2303 365 303 229 0 63 0
[pid=12248] ppid=12231 vsize=303824 CPUtime=3.8
/proc/12248/stat : 12248 (gringo) R 12231 12231 1745 0 -1 4202496 72359 0 1 0 359 21 0 0 20 0 1 0 117964969 311115776 63081 18446744073709551615 4194304 6531320 140733545291552 140733545288360 5502363 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/12248/statm: 75956 63081 283 571 0 75377 0
Current children cumulated CPU time (s) 6.74
Current children cumulated vsize (KiB) 313036

[startup+8.00034 s]
/proc/loadavg: 1.06 1.05 1.06 2/67 12258
/proc/meminfo: memFree=182796/1022884 swapFree=0/0
[pid=12231] ppid=12230 vsize=9212 CPUtime=6.98
/proc/12231/stat : 12231 (aspcud-full) S 12230 12231 1745 0 -1 4202496 810 101022 0 8 1 0 649 48 20 0 1 0 117964647 9433088 365 18446744073709551615 4194304 5129932 140736138019776 140736138017840 140350670632030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12231/statm: 2303 365 303 229 0 63 0
[pid=12257] ppid=12231 vsize=84972 CPUtime=0.53
/proc/12257/stat : 12257 (clasp) R 12231 12231 1745 0 -1 4202496 24723 0 0 0 46 7 0 0 20 0 1 0 117965390 87011328 20709 18446744073709551615 4194304 6238623 140734672021632 140734672019560 4606253 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/12257/statm: 21243 20709 246 500 0 20740 0
[pid=12258] ppid=12231 vsize=22040 CPUtime=0
/proc/12258/stat : 12258 (parse.py) S 12231 12231 1745 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 117965390 22568960 1128 18446744073709551615 4194304 6642060 140736270507872 140736270506232 139973186258720 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/12258/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 7.51
Current children cumulated vsize (KiB) 116224

[startup+8.20035 s]
/proc/loadavg: 1.06 1.05 1.06 2/67 12258
/proc/meminfo: memFree=182796/1022884 swapFree=0/0
[pid=12231] ppid=12230 vsize=9212 CPUtime=6.98
/proc/12231/stat : 12231 (aspcud-full) S 12230 12231 1745 0 -1 4202496 810 101022 0 8 1 0 649 48 20 0 1 0 117964647 9433088 365 18446744073709551615 4194304 5129932 140736138019776 140736138017840 140350670632030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12231/statm: 2303 365 303 229 0 63 0
[pid=12257] ppid=12231 vsize=84972 CPUtime=0.67
/proc/12257/stat : 12257 (clasp) R 12231 12231 1745 0 -1 4202496 24743 0 0 0 60 7 0 0 20 0 1 0 117965390 87011328 20729 18446744073709551615 4194304 6238623 140734672021632 140734672018656 4586431 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/12257/statm: 21243 20729 263 500 0 20740 0
[pid=12258] ppid=12231 vsize=22040 CPUtime=0
/proc/12258/stat : 12258 (parse.py) S 12231 12231 1745 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 117965390 22568960 1128 18446744073709551615 4194304 6642060 140736270507872 140736270506232 139973186258720 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/12258/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 7.65
Current children cumulated vsize (KiB) 116224

[startup+8.30033 s]
/proc/loadavg: 1.06 1.05 1.06 2/67 12258
/proc/meminfo: memFree=182796/1022884 swapFree=0/0
[pid=12231] ppid=12230 vsize=9212 CPUtime=6.98
/proc/12231/stat : 12231 (aspcud-full) S 12230 12231 1745 0 -1 4202496 810 101022 0 8 1 0 649 48 20 0 1 0 117964647 9433088 365 18446744073709551615 4194304 5129932 140736138019776 140736138017840 140350670632030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12231/statm: 2303 365 303 229 0 63 0
[pid=12257] ppid=12231 vsize=84972 CPUtime=0.73
/proc/12257/stat : 12257 (clasp) R 12231 12231 1745 0 -1 4202496 24743 0 0 0 66 7 0 0 20 0 1 0 117965390 87011328 20729 18446744073709551615 4194304 6238623 140734672021632 140734672018656 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/12257/statm: 21243 20729 263 500 0 20740 0
[pid=12258] ppid=12231 vsize=22040 CPUtime=0
/proc/12258/stat : 12258 (parse.py) S 12231 12231 1745 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 117965390 22568960 1128 18446744073709551615 4194304 6642060 140736270507872 140736270506232 139973186258720 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/12258/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 7.71
Current children cumulated vsize (KiB) 116224

Child status: 0
Real time (s): 8.393
CPU time (s): 7.82049
CPU user time (s): 7.22445
CPU system time (s): 0.596037
CPU usage (%): 93.1787
Max. virtual memory (cumulated for all children) (KiB): 313036

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.22445
system time used= 0.596037
maximum resident set size= 252324
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 128202
page faults= 8
swaps= 0
block input operations= 42816
block output operations= 35096
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 101
involuntary context switches= 1085

runsolver used 0.020001 second user time and 0.040002 second system time

The end