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/slowlink/install/rand308.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand308.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/install/rand308.cudf.result -sum(changed,installedsize),-count(removed),-notuptodate(solution),-count(changed) 

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: 0.86 1.02 1.15 2/59 19562
/proc/meminfo: memFree=566700/1022884 swapFree=0/0
[pid=19562] ppid=19561 vsize=3152 CPUtime=0
/proc/19562/stat : 19562 (runsolver) R 19561 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 119981618 3227648 33 18446744073709551615 134512640 134586868 4292346368 4292344416 4151821360 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/19562/statm: 788 33 0 19 0 73 0

[startup+0.190626 s]
/proc/loadavg: 0.86 1.02 1.15 2/59 19562
/proc/meminfo: memFree=566700/1022884 swapFree=0/0
[pid=19562] ppid=19561 vsize=9212 CPUtime=0.03
/proc/19562/stat : 19562 (aspcud-full) S 19561 19562 1750 0 -1 4202496 739 3615 0 0 0 0 2 1 20 0 1 0 119981618 9433088 364 18446744073709551615 4194304 5129932 140733659809840 140733659808496 140124975539294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19562/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200381 s]
/proc/loadavg: 0.86 1.02 1.15 2/59 19562
/proc/meminfo: memFree=566700/1022884 swapFree=0/0
[pid=19562] ppid=19561 vsize=9212 CPUtime=0.03
/proc/19562/stat : 19562 (aspcud-full) S 19561 19562 1750 0 -1 4202496 739 3615 0 0 0 0 2 1 20 0 1 0 119981618 9433088 364 18446744073709551615 4194304 5129932 140733659809840 140733659808496 140124975539294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19562/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300339 s]
/proc/loadavg: 0.86 1.02 1.15 2/59 19562
/proc/meminfo: memFree=566700/1022884 swapFree=0/0
[pid=19562] ppid=19561 vsize=9212 CPUtime=0.03
/proc/19562/stat : 19562 (aspcud-full) S 19561 19562 1750 0 -1 4202496 739 3615 0 0 0 0 2 1 20 0 1 0 119981618 9433088 364 18446744073709551615 4194304 5129932 140733659809840 140733659808496 140124975539294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19562/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700199 s]
/proc/loadavg: 0.86 1.02 1.15 2/59 19562
/proc/meminfo: memFree=566700/1022884 swapFree=0/0
[pid=19562] ppid=19561 vsize=9212 CPUtime=0.03
/proc/19562/stat : 19562 (aspcud-full) S 19561 19562 1750 0 -1 4202496 739 3615 0 0 0 0 2 1 20 0 1 0 119981618 9433088 364 18446744073709551615 4194304 5129932 140733659809840 140733659808496 140124975539294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19562/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.5003 s]
/proc/loadavg: 0.86 1.02 1.15 2/61 19578
/proc/meminfo: memFree=529228/1022884 swapFree=0/0
[pid=19562] ppid=19561 vsize=9212 CPUtime=0.03
/proc/19562/stat : 19562 (aspcud-full) S 19561 19562 1750 0 -1 4202496 739 3615 0 0 0 0 2 1 20 0 1 0 119981618 9433088 364 18446744073709551615 4194304 5129932 140733659809840 140733659808496 140124975539294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19562/statm: 2303 364 303 229 0 63 0
[pid=19578] ppid=19562 vsize=50676 CPUtime=1.36
/proc/19578/stat : 19578 (cudf2lp) R 19562 19562 1750 0 -1 4202496 14256 0 0 0 131 5 0 0 20 0 1 0 119981620 51892224 10857 18446744073709551615 4194304 5690517 140733907042720 140733907040360 4293680 0 0 16781316 0 0 0 0 17 0 0 0 9 0 0
/proc/19578/statm: 12669 10857 160 366 0 12300 0
Current children cumulated CPU time (s) 1.39
Current children cumulated vsize (KiB) 59888

[startup+3.10026 s]
/proc/loadavg: 0.86 1.02 1.15 2/61 19578
/proc/meminfo: memFree=498352/1022884 swapFree=0/0
[pid=19562] ppid=19561 vsize=9212 CPUtime=0.03
/proc/19562/stat : 19562 (aspcud-full) S 19561 19562 1750 0 -1 4202496 739 3615 0 0 0 0 2 1 20 0 1 0 119981618 9433088 364 18446744073709551615 4194304 5129932 140733659809840 140733659808496 140124975539294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19562/statm: 2303 364 303 229 0 63 0
[pid=19578] ppid=19562 vsize=93028 CPUtime=2.93
/proc/19578/stat : 19578 (cudf2lp) R 19562 19562 1750 0 -1 4202496 26860 0 0 0 283 10 0 0 20 0 1 0 119981620 95260672 20132 18446744073709551615 4194304 5690517 140733907042720 140733907040360 4360920 0 0 16781316 0 0 0 0 17 0 0 0 11 0 0
/proc/19578/statm: 23257 20132 160 366 0 22888 0
Current children cumulated CPU time (s) 2.96
Current children cumulated vsize (KiB) 102240

[startup+6.30027 s]
/proc/loadavg: 0.87 1.02 1.15 2/61 19587
/proc/meminfo: memFree=482232/1022884 swapFree=0/0
[pid=19562] ppid=19561 vsize=9212 CPUtime=4.15
/proc/19562/stat : 19562 (aspcud-full) S 19561 19562 1750 0 -1 4202496 765 42937 0 0 0 0 392 23 20 0 1 0 119981618 9433088 364 18446744073709551615 4194304 5129932 140733659809840 140733659808496 140124975539294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19562/statm: 2303 364 303 229 0 63 0
[pid=19579] ppid=19562 vsize=111164 CPUtime=1.78
/proc/19579/stat : 19579 (gringo) R 19562 19562 1750 0 -1 4202496 29832 0 0 0 164 14 0 0 20 0 1 0 119982058 113831936 24649 18446744073709551615 4194304 6531320 140734984468480 140734984465096 5101987 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/19579/statm: 27791 24649 281 571 0 27212 0
Current children cumulated CPU time (s) 5.93
Current children cumulated vsize (KiB) 120376

[startup+12.7003 s]
/proc/loadavg: 0.96 1.04 1.16 3/64 19698
/proc/meminfo: memFree=339112/1022884 swapFree=0/0
[pid=19562] ppid=19561 vsize=9212 CPUtime=9.44
/proc/19562/stat : 19562 (aspcud-full) S 19561 19562 1750 0 -1 4202496 806 153885 0 0 0 0 875 69 20 0 1 0 119981618 9433088 364 18446744073709551615 4194304 5129932 140733659809840 140733659807904 140124975539294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19562/statm: 2303 364 303 229 0 63 0
[pid=19652] ppid=19562 vsize=142576 CPUtime=1.52
/proc/19652/stat : 19652 (clasp) R 19562 19562 1750 0 -1 4202496 41234 0 0 0 140 12 0 0 20 0 1 0 119982671 145997824 35060 18446744073709551615 4194304 6238623 140736214208464 140736214205488 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19652/statm: 35644 35060 263 500 0 35141 0
[pid=19653] ppid=19562 vsize=22040 CPUtime=0.01
/proc/19653/stat : 19653 (parse.py) S 19562 19562 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 119982671 22568960 1128 18446744073709551615 4194304 6642060 140735385197872 140735385196232 140667472459552 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19653/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 10.97
Current children cumulated vsize (KiB) 173828

[startup+25.5003 s]
/proc/loadavg: 1.12 1.07 1.17 2/66 19796
/proc/meminfo: memFree=174976/1022884 swapFree=0/0
[pid=19562] ppid=19561 vsize=9212 CPUtime=9.44
/proc/19562/stat : 19562 (aspcud-full) S 19561 19562 1750 0 -1 4202496 806 153885 0 0 0 0 875 69 20 0 1 0 119981618 9433088 364 18446744073709551615 4194304 5129932 140733659809840 140733659807904 140124975539294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19562/statm: 2303 364 303 229 0 63 0
[pid=19652] ppid=19562 vsize=142576 CPUtime=10.53
/proc/19652/stat : 19652 (clasp) R 19562 19562 1750 0 -1 4202496 41312 0 0 0 1041 12 0 0 20 0 1 0 119982671 145997824 35138 18446744073709551615 4194304 6238623 140736214208464 140736214205488 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19652/statm: 35644 35138 263 500 0 35141 0
[pid=19653] ppid=19562 vsize=22040 CPUtime=0.01
/proc/19653/stat : 19653 (parse.py) S 19562 19562 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 119982671 22568960 1128 18446744073709551615 4194304 6642060 140735385197872 140735385196232 140667472459552 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19653/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 19.98
Current children cumulated vsize (KiB) 173828
heavy processes:

[startup+51.1003 s]
/proc/loadavg: 1.14 1.08 1.17 2/62 19832
/proc/meminfo: memFree=151592/1022884 swapFree=0/0
[pid=19562] ppid=19561 vsize=9212 CPUtime=9.44
/proc/19562/stat : 19562 (aspcud-full) S 19561 19562 1750 0 -1 4202496 806 153885 0 0 0 0 875 69 20 0 1 0 119981618 9433088 364 18446744073709551615 4194304 5129932 140733659809840 140733659807904 140124975539294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19562/statm: 2303 364 303 229 0 63 0
[pid=19652] ppid=19562 vsize=142576 CPUtime=35.21
/proc/19652/stat : 19652 (clasp) R 19562 19562 1750 0 -1 4202496 41410 0 0 0 3507 14 0 0 20 0 1 0 119982671 145997824 35236 18446744073709551615 4194304 6238623 140736214208464 140736214205488 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19652/statm: 35644 35236 263 500 0 35141 0
[pid=19653] ppid=19562 vsize=22040 CPUtime=0.01
/proc/19653/stat : 19653 (parse.py) S 19562 19562 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 119982671 22568960 1128 18446744073709551615 4194304 6642060 140735385197872 140735385196232 140667472459552 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19653/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 44.66
Current children cumulated vsize (KiB) 173828

[startup+102.3 s]
/proc/loadavg: 1.06 1.06 1.16 2/62 19832
/proc/meminfo: memFree=151716/1022884 swapFree=0/0
[pid=19562] ppid=19561 vsize=9212 CPUtime=9.44
/proc/19562/stat : 19562 (aspcud-full) S 19561 19562 1750 0 -1 4202496 806 153885 0 0 0 0 875 69 20 0 1 0 119981618 9433088 364 18446744073709551615 4194304 5129932 140733659809840 140733659807904 140124975539294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19562/statm: 2303 364 303 229 0 63 0
[pid=19652] ppid=19562 vsize=142576 CPUtime=86.02
/proc/19652/stat : 19652 (clasp) R 19562 19562 1750 0 -1 4202496 41489 0 0 0 8588 14 0 0 20 0 1 0 119982671 145997824 35315 18446744073709551615 4194304 6238623 140736214208464 140736214205488 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19652/statm: 35644 35315 263 500 0 35141 0
[pid=19653] ppid=19562 vsize=22040 CPUtime=0.01
/proc/19653/stat : 19653 (parse.py) S 19562 19562 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 119982671 22568960 1128 18446744073709551615 4194304 6642060 140735385197872 140735385196232 140667472459552 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19653/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 95.47
Current children cumulated vsize (KiB) 173828

[startup+162.3 s]
/proc/loadavg: 1.02 1.05 1.14 2/62 19832
/proc/meminfo: memFree=140804/1022884 swapFree=0/0
[pid=19562] ppid=19561 vsize=9212 CPUtime=9.44
/proc/19562/stat : 19562 (aspcud-full) S 19561 19562 1750 0 -1 4202496 806 153885 0 0 0 0 875 69 20 0 1 0 119981618 9433088 364 18446744073709551615 4194304 5129932 140733659809840 140733659807904 140124975539294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19562/statm: 2303 364 303 229 0 63 0
[pid=19652] ppid=19562 vsize=153600 CPUtime=145.56
/proc/19652/stat : 19652 (clasp) R 19562 19562 1750 0 -1 4202496 44234 0 0 0 14541 15 0 0 20 0 1 0 119982671 157286400 38060 18446744073709551615 4194304 6238623 140736214208464 140736214205016 4687704 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19652/statm: 38400 38060 263 500 0 37897 0
[pid=19653] ppid=19562 vsize=22040 CPUtime=0.01
/proc/19653/stat : 19653 (parse.py) S 19562 19562 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 119982671 22568960 1128 18446744073709551615 4194304 6642060 140735385197872 140735385196232 140667472459552 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19653/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 155.01
Current children cumulated vsize (KiB) 184852

[startup+222.304 s]
/proc/loadavg: 1.00 1.04 1.13 2/62 19832
/proc/meminfo: memFree=69256/1022884 swapFree=0/0
[pid=19562] ppid=19561 vsize=9212 CPUtime=9.44
/proc/19562/stat : 19562 (aspcud-full) S 19561 19562 1750 0 -1 4202496 806 153885 0 0 0 0 875 69 20 0 1 0 119981618 9433088 364 18446744073709551615 4194304 5129932 140733659809840 140733659807904 140124975539294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19562/statm: 2303 364 303 229 0 63 0
[pid=19652] ppid=19562 vsize=226704 CPUtime=205.12
/proc/19652/stat : 19652 (clasp) R 19562 19562 1750 0 -1 4202496 62111 0 0 0 20488 24 0 0 20 0 1 0 119982671 232144896 55937 18446744073709551615 4194304 6238623 140736214208464 140736214205016 4306765 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19652/statm: 56676 55937 263 500 0 56173 0
[pid=19653] ppid=19562 vsize=22040 CPUtime=0.01
/proc/19653/stat : 19653 (parse.py) S 19562 19562 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 119982671 22568960 1128 18446744073709551615 4194304 6642060 140735385197872 140735385196232 140667472459552 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19653/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 214.57
Current children cumulated vsize (KiB) 257956

[startup+282.3 s]
/proc/loadavg: 1.05 1.04 1.13 2/62 19832
/proc/meminfo: memFree=39992/1022884 swapFree=0/0
[pid=19562] ppid=19561 vsize=9212 CPUtime=9.44
/proc/19562/stat : 19562 (aspcud-full) S 19561 19562 1750 0 -1 4202496 806 153885 0 0 0 0 875 69 20 0 1 0 119981618 9433088 364 18446744073709551615 4194304 5129932 140733659809840 140733659807904 140124975539294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19562/statm: 2303 364 303 229 0 63 0
[pid=19652] ppid=19562 vsize=256520 CPUtime=264.67
/proc/19652/stat : 19652 (clasp) R 19562 19562 1750 0 -1 4202496 69410 0 0 0 26438 29 0 0 20 0 1 0 119982671 262676480 63236 18446744073709551615 4194304 6238623 140736214208464 140736214205016 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19652/statm: 64130 63236 263 500 0 63627 0
[pid=19653] ppid=19562 vsize=22040 CPUtime=0.01
/proc/19653/stat : 19653 (parse.py) S 19562 19562 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 119982671 22568960 1128 18446744073709551615 4194304 6642060 140735385197872 140735385196232 140667472459552 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19653/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 274.12
Current children cumulated vsize (KiB) 287772



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+308.4 s]
/proc/loadavg: 1.03 1.04 1.12 2/62 19832
/proc/meminfo: memFree=39868/1022884 swapFree=0/0
[pid=19562] ppid=19561 vsize=9212 CPUtime=9.44
/proc/19562/stat : 19562 (aspcud-full) S 19561 19562 1750 0 -1 4202496 806 153885 0 0 0 0 875 69 20 0 1 0 119981618 9433088 364 18446744073709551615 4194304 5129932 140733659809840 140733659807904 140124975539294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19562/statm: 2303 364 303 229 0 63 0
[pid=19652] ppid=19562 vsize=256520 CPUtime=290.58
/proc/19652/stat : 19652 (clasp) R 19562 19562 1750 0 -1 4202496 69432 0 0 0 29029 29 0 0 20 0 1 0 119982671 262676480 63258 18446744073709551615 4194304 6238623 140736214208464 140736214205488 4684920 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19652/statm: 64130 63258 263 500 0 63627 0
[pid=19653] ppid=19562 vsize=22040 CPUtime=0.01
/proc/19653/stat : 19653 (parse.py) S 19562 19562 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 119982671 22568960 1128 18446744073709551615 4194304 6642060 140735385197872 140735385196232 140667472459552 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19653/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.03
Current children cumulated vsize (KiB) 287772

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

[startup+308.4 s]
/proc/loadavg: 1.03 1.04 1.12 2/62 19832
/proc/meminfo: memFree=39868/1022884 swapFree=0/0
[pid=19562] ppid=19561 vsize=9212 CPUtime=9.44
/proc/19562/stat : 19562 (aspcud-full) S 19561 19562 1750 0 -1 4202496 806 153885 0 0 0 0 875 69 20 0 1 0 119981618 9433088 364 18446744073709551615 4194304 5129932 140733659809840 140733659807904 140124975539294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19562/statm: 2303 364 303 229 0 63 0
[pid=19652] ppid=19562 vsize=256520 CPUtime=290.58
/proc/19652/stat : 19652 (clasp) R 19562 19562 1750 0 -1 4202496 69432 0 0 0 29029 29 0 0 20 0 1 0 119982671 262676480 63258 18446744073709551615 4194304 6238623 140736214208464 140736214205488 4684920 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19652/statm: 64130 63258 263 500 0 63627 0
[pid=19653] ppid=19562 vsize=22040 CPUtime=0.01
/proc/19653/stat : 19653 (parse.py) S 19562 19562 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 119982671 22568960 1128 18446744073709551615 4194304 6642060 140735385197872 140735385196232 140667472459552 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19653/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.03
Current children cumulated vsize (KiB) 287772

Child status: 0
Real time (s): 308.437
CPU time (s): 300.087
CPU user time (s): 299.063
CPU system time (s): 1.02406
CPU usage (%): 97.2927
Max. virtual memory (cumulated for all children) (KiB): 476192

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.063
system time used= 1.02406
maximum resident set size= 406656
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 225753
page faults= 0
swaps= 0
block input operations= 68432
block output operations= 51216
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 87
involuntary context switches= 38137

runsolver used 0.500031 second user time and 1.15607 second system time

The end