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/trendy-size/upgrade/easy/rand929.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/easy/rand929.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/upgrade/easy/rand929.cudf.result -count(removed),-sum(solution,installedsize),-notuptodate(solution),-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: 0.97 0.98 0.95 2/64 16856
/proc/meminfo: memFree=429276/1022884 swapFree=0/0
[pid=16856] ppid=16855 vsize=9204 CPUtime=0
/proc/16856/stat : 16856 (aspcud-full) S 16855 16856 1745 0 -1 4202496 433 0 0 0 0 0 0 0 20 0 1 0 119448644 9424896 332 18446744073709551615 4194304 5129932 140734196964016 140734196961480 140216292706080 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/16856/statm: 2301 332 272 229 0 61 0

[startup+0.130093 s]
/proc/loadavg: 0.97 0.98 0.95 2/64 16856
/proc/meminfo: memFree=429276/1022884 swapFree=0/0
[pid=16856] ppid=16855 vsize=9212 CPUtime=0.06
/proc/16856/stat : 16856 (aspcud-full) S 16855 16856 1745 0 -1 4202496 740 3618 0 6 0 1 3 2 20 0 1 0 119448644 9433088 365 18446744073709551615 4194304 5129932 140734196964016 140734196962672 140216292562014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16856/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.200317 s]
/proc/loadavg: 0.97 0.98 0.95 2/64 16856
/proc/meminfo: memFree=429276/1022884 swapFree=0/0
[pid=16856] ppid=16855 vsize=9212 CPUtime=0.06
/proc/16856/stat : 16856 (aspcud-full) S 16855 16856 1745 0 -1 4202496 740 3618 0 6 0 1 3 2 20 0 1 0 119448644 9433088 365 18446744073709551615 4194304 5129932 140734196964016 140734196962672 140216292562014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16856/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.300305 s]
/proc/loadavg: 0.97 0.98 0.95 2/64 16856
/proc/meminfo: memFree=429276/1022884 swapFree=0/0
[pid=16856] ppid=16855 vsize=9212 CPUtime=0.06
/proc/16856/stat : 16856 (aspcud-full) S 16855 16856 1745 0 -1 4202496 740 3618 0 6 0 1 3 2 20 0 1 0 119448644 9433088 365 18446744073709551615 4194304 5129932 140734196964016 140734196962672 140216292562014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16856/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.700277 s]
/proc/loadavg: 0.97 0.98 0.95 2/64 16856
/proc/meminfo: memFree=429276/1022884 swapFree=0/0
[pid=16856] ppid=16855 vsize=9212 CPUtime=0.06
/proc/16856/stat : 16856 (aspcud-full) S 16855 16856 1745 0 -1 4202496 740 3618 0 6 0 1 3 2 20 0 1 0 119448644 9433088 365 18446744073709551615 4194304 5129932 140734196964016 140734196962672 140216292562014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16856/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 0.97 0.98 0.95 2/66 16872
/proc/meminfo: memFree=395152/1022884 swapFree=0/0
[pid=16856] ppid=16855 vsize=9212 CPUtime=0.06
/proc/16856/stat : 16856 (aspcud-full) S 16855 16856 1745 0 -1 4202496 740 3618 0 6 0 1 3 2 20 0 1 0 119448644 9433088 365 18446744073709551615 4194304 5129932 140734196964016 140734196962672 140216292562014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16856/statm: 2303 365 303 229 0 63 0
[pid=16872] ppid=16856 vsize=55524 CPUtime=1.38
/proc/16872/stat : 16872 (cudf2lp) R 16856 16856 1745 0 -1 4202496 13675 0 0 0 133 5 0 0 20 0 1 0 119448651 56856576 11942 18446744073709551615 4194304 5690517 140734667777856 140734667774024 4970346 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/16872/statm: 13881 11942 159 366 0 13512 0
Current children cumulated CPU time (s) 1.44
Current children cumulated vsize (KiB) 64736

[startup+3.10032 s]
/proc/loadavg: 0.97 0.98 0.95 2/66 16872
/proc/meminfo: memFree=364400/1022884 swapFree=0/0
[pid=16856] ppid=16855 vsize=9212 CPUtime=0.06
/proc/16856/stat : 16856 (aspcud-full) S 16855 16856 1745 0 -1 4202496 740 3618 0 6 0 1 3 2 20 0 1 0 119448644 9433088 365 18446744073709551615 4194304 5129932 140734196964016 140734196962672 140216292562014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16856/statm: 2303 365 303 229 0 63 0
[pid=16872] ppid=16856 vsize=72092 CPUtime=2.96
/proc/16872/stat : 16872 (cudf2lp) R 16856 16856 1745 0 -1 4202496 23822 0 0 0 286 10 0 0 20 0 1 0 119448651 73822208 17759 18446744073709551615 4194304 5690517 140734667777856 140734667775224 4957056 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/16872/statm: 18023 17759 174 366 0 17654 0
Current children cumulated CPU time (s) 3.02
Current children cumulated vsize (KiB) 81304

[startup+6.30031 s]
/proc/loadavg: 0.97 0.98 0.95 2/66 16873
/proc/meminfo: memFree=301656/1022884 swapFree=0/0
[pid=16856] ppid=16855 vsize=9212 CPUtime=3.1
/proc/16856/stat : 16856 (aspcud-full) S 16855 16856 1745 0 -1 4202496 766 27442 0 6 0 1 295 14 20 0 1 0 119448644 9433088 365 18446744073709551615 4194304 5129932 140734196964016 140734196962672 140216292562014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16856/statm: 2303 365 303 229 0 63 0
[pid=16873] ppid=16856 vsize=161620 CPUtime=3.08
/proc/16873/stat : 16873 (gringo) R 16856 16856 1745 0 -1 4202496 40577 0 0 0 293 15 0 0 20 0 1 0 119448962 165498880 36135 18446744073709551615 4194304 6531320 140736560898032 140736560894040 4596844 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/16873/statm: 40405 36135 281 571 0 39826 0
Current children cumulated CPU time (s) 6.18
Current children cumulated vsize (KiB) 170832

[startup+12.7004 s]
/proc/loadavg: 0.97 0.98 0.95 2/67 16875
/proc/meminfo: memFree=269284/1022884 swapFree=0/0
[pid=16856] ppid=16855 vsize=9212 CPUtime=10.47
/proc/16856/stat : 16856 (aspcud-full) S 16855 16856 1745 0 -1 4202496 806 135298 0 6 0 1 975 71 20 0 1 0 119448644 9433088 365 18446744073709551615 4194304 5129932 140734196964016 140734196962080 140216292562014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16856/statm: 2303 365 303 229 0 63 0
[pid=16874] ppid=16856 vsize=138472 CPUtime=1.98
/proc/16874/stat : 16874 (clasp) R 16856 16856 1745 0 -1 4202496 40225 0 0 0 182 16 0 0 20 0 1 0 119449711 141795328 34063 18446744073709551615 4194304 6238623 140733433702816 140733433699840 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16874/statm: 34618 34063 263 500 0 34115 0
[pid=16875] ppid=16856 vsize=22040 CPUtime=0.02
/proc/16875/stat : 16875 (parse.py) S 16856 16856 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 119449711 22568960 1128 18446744073709551615 4194304 6642060 140735504477024 140735504475384 139702227568416 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16875/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.47
Current children cumulated vsize (KiB) 169724

[startup+25.5004 s]
/proc/loadavg: 0.98 0.98 0.95 2/67 16875
/proc/meminfo: memFree=268912/1022884 swapFree=0/0
[pid=16856] ppid=16855 vsize=9212 CPUtime=10.47
/proc/16856/stat : 16856 (aspcud-full) S 16855 16856 1745 0 -1 4202496 806 135298 0 6 0 1 975 71 20 0 1 0 119448644 9433088 365 18446744073709551615 4194304 5129932 140734196964016 140734196962080 140216292562014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16856/statm: 2303 365 303 229 0 63 0
[pid=16874] ppid=16856 vsize=138472 CPUtime=14.65
/proc/16874/stat : 16874 (clasp) R 16856 16856 1745 0 -1 4202496 40376 0 0 0 1449 16 0 0 20 0 1 0 119449711 141795328 34214 18446744073709551615 4194304 6238623 140733433702816 140733433699840 4687688 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16874/statm: 34618 34214 264 500 0 34115 0
[pid=16875] ppid=16856 vsize=22040 CPUtime=0.02
/proc/16875/stat : 16875 (parse.py) S 16856 16856 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 119449711 22568960 1128 18446744073709551615 4194304 6642060 140735504477024 140735504475384 139702227568416 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16875/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.14
Current children cumulated vsize (KiB) 169724

[startup+51.1003 s]
/proc/loadavg: 0.98 0.98 0.95 2/67 16875
/proc/meminfo: memFree=268912/1022884 swapFree=0/0
[pid=16856] ppid=16855 vsize=9212 CPUtime=10.47
/proc/16856/stat : 16856 (aspcud-full) S 16855 16856 1745 0 -1 4202496 806 135298 0 6 0 1 975 71 20 0 1 0 119448644 9433088 365 18446744073709551615 4194304 5129932 140734196964016 140734196962080 140216292562014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16856/statm: 2303 365 303 229 0 63 0
[pid=16874] ppid=16856 vsize=138472 CPUtime=39.99
/proc/16874/stat : 16874 (clasp) R 16856 16856 1745 0 -1 4202496 40376 0 0 0 3983 16 0 0 20 0 1 0 119449711 141795328 34214 18446744073709551615 4194304 6238623 140733433702816 140733433699840 4662328 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16874/statm: 34618 34214 264 500 0 34115 0
[pid=16875] ppid=16856 vsize=22040 CPUtime=0.02
/proc/16875/stat : 16875 (parse.py) S 16856 16856 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 119449711 22568960 1128 18446744073709551615 4194304 6642060 140735504477024 140735504475384 139702227568416 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16875/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.48
Current children cumulated vsize (KiB) 169724

[startup+102.3 s]
/proc/loadavg: 0.99 0.98 0.95 2/67 16875
/proc/meminfo: memFree=214104/1022884 swapFree=0/0
[pid=16856] ppid=16855 vsize=9212 CPUtime=10.47
/proc/16856/stat : 16856 (aspcud-full) S 16855 16856 1745 0 -1 4202496 806 135298 0 6 0 1 975 71 20 0 1 0 119448644 9433088 365 18446744073709551615 4194304 5129932 140734196964016 140734196962080 140216292562014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16856/statm: 2303 365 303 229 0 63 0
[pid=16874] ppid=16856 vsize=192692 CPUtime=90.81
/proc/16874/stat : 16874 (clasp) R 16856 16856 1745 0 -1 4202496 54035 0 0 0 9055 26 0 0 20 0 1 0 119449711 197316608 47873 18446744073709551615 4194304 6238623 140733433702816 140733433699368 4332270 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16874/statm: 48173 47873 264 500 0 47670 0
[pid=16875] ppid=16856 vsize=22040 CPUtime=0.02
/proc/16875/stat : 16875 (parse.py) S 16856 16856 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 119449711 22568960 1128 18446744073709551615 4194304 6642060 140735504477024 140735504475384 139702227568416 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16875/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.3
Current children cumulated vsize (KiB) 223944

[startup+162.3 s]
/proc/loadavg: 0.99 0.98 0.95 2/67 16875
/proc/meminfo: memFree=166240/1022884 swapFree=0/0
[pid=16856] ppid=16855 vsize=9212 CPUtime=10.47
/proc/16856/stat : 16856 (aspcud-full) S 16855 16856 1745 0 -1 4202496 806 135298 0 6 0 1 975 71 20 0 1 0 119448644 9433088 365 18446744073709551615 4194304 5129932 140734196964016 140734196962080 140216292562014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16856/statm: 2303 365 303 229 0 63 0
[pid=16874] ppid=16856 vsize=240524 CPUtime=150.36
/proc/16874/stat : 16874 (clasp) R 16856 16856 1745 0 -1 4202496 65955 0 0 0 15006 30 0 0 20 0 1 0 119449711 246296576 59793 18446744073709551615 4194304 6238623 140733433702816 140733433699368 4687967 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16874/statm: 60131 59793 264 500 0 59628 0
[pid=16875] ppid=16856 vsize=22040 CPUtime=0.02
/proc/16875/stat : 16875 (parse.py) S 16856 16856 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 119449711 22568960 1128 18446744073709551615 4194304 6642060 140735504477024 140735504475384 139702227568416 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16875/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.85
Current children cumulated vsize (KiB) 271776

[startup+222.303 s]
/proc/loadavg: 0.99 0.98 0.95 2/67 16875
/proc/meminfo: memFree=95932/1022884 swapFree=0/0
[pid=16856] ppid=16855 vsize=9212 CPUtime=10.47
/proc/16856/stat : 16856 (aspcud-full) S 16855 16856 1745 0 -1 4202496 806 135298 0 6 0 1 975 71 20 0 1 0 119448644 9433088 365 18446744073709551615 4194304 5129932 140734196964016 140734196962080 140216292562014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16856/statm: 2303 365 303 229 0 63 0
[pid=16874] ppid=16856 vsize=310888 CPUtime=209.93
/proc/16874/stat : 16874 (clasp) R 16856 16856 1745 0 -1 4202496 83485 0 0 0 20952 41 0 0 20 0 1 0 119449711 318349312 77323 18446744073709551615 4194304 6238623 140733433702816 140733433699368 4331882 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16874/statm: 77722 77323 264 500 0 77219 0
[pid=16875] ppid=16856 vsize=22040 CPUtime=0.02
/proc/16875/stat : 16875 (parse.py) S 16856 16856 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 119449711 22568960 1128 18446744073709551615 4194304 6642060 140735504477024 140735504475384 139702227568416 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16875/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 220.42
Current children cumulated vsize (KiB) 342140

[startup+282.3 s]
/proc/loadavg: 0.99 0.98 0.95 2/67 16875
/proc/meminfo: memFree=92088/1022884 swapFree=0/0
[pid=16856] ppid=16855 vsize=9212 CPUtime=10.47
/proc/16856/stat : 16856 (aspcud-full) S 16855 16856 1745 0 -1 4202496 806 135298 0 6 0 1 975 71 20 0 1 0 119448644 9433088 365 18446744073709551615 4194304 5129932 140734196964016 140734196962080 140216292562014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16856/statm: 2303 365 303 229 0 63 0
[pid=16874] ppid=16856 vsize=314724 CPUtime=269.44
/proc/16874/stat : 16874 (clasp) R 16856 16856 1745 0 -1 4202496 84461 0 0 0 26903 41 0 0 20 0 1 0 119449711 322277376 78299 18446744073709551615 4194304 6238623 140733433702816 140733433699368 4404425 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16874/statm: 78681 78299 264 500 0 78178 0
[pid=16875] ppid=16856 vsize=22040 CPUtime=0.02
/proc/16875/stat : 16875 (parse.py) S 16856 16856 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 119449711 22568960 1128 18446744073709551615 4194304 6642060 140735504477024 140735504475384 139702227568416 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16875/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 279.93
Current children cumulated vsize (KiB) 345976



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.603 s]
/proc/loadavg: 0.99 0.98 0.95 2/67 16875
/proc/meminfo: memFree=91468/1022884 swapFree=0/0
[pid=16856] ppid=16855 vsize=9212 CPUtime=10.47
/proc/16856/stat : 16856 (aspcud-full) S 16855 16856 1745 0 -1 4202496 806 135298 0 6 0 1 975 71 20 0 1 0 119448644 9433088 365 18446744073709551615 4194304 5129932 140734196964016 140734196962080 140216292562014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16856/statm: 2303 365 303 229 0 63 0
[pid=16874] ppid=16856 vsize=315384 CPUtime=289.6
/proc/16874/stat : 16874 (clasp) R 16856 16856 1745 0 -1 4202496 84612 0 0 0 28918 42 0 0 20 0 1 0 119449711 322953216 78450 18446744073709551615 4194304 6238623 140733433702816 140733433699368 4635239 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16874/statm: 78846 78450 264 500 0 78343 0
[pid=16875] ppid=16856 vsize=22040 CPUtime=0.02
/proc/16875/stat : 16875 (parse.py) S 16856 16856 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 119449711 22568960 1128 18446744073709551615 4194304 6642060 140735504477024 140735504475384 139702227568416 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16875/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.09
Current children cumulated vsize (KiB) 346636

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+302.603 s]
/proc/loadavg: 0.99 0.98 0.95 2/67 16875
/proc/meminfo: memFree=91468/1022884 swapFree=0/0
[pid=16856] ppid=16855 vsize=9212 CPUtime=10.47
/proc/16856/stat : 16856 (aspcud-full) S 16855 16856 1745 0 -1 4202496 806 135298 0 6 0 1 975 71 20 0 1 0 119448644 9433088 365 18446744073709551615 4194304 5129932 140734196964016 140734196962080 140216292562014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/16856/statm: 2303 365 303 229 0 63 0
[pid=16874] ppid=16856 vsize=315384 CPUtime=289.6
/proc/16874/stat : 16874 (clasp) R 16856 16856 1745 0 -1 4202496 84612 0 0 0 28918 42 0 0 20 0 1 0 119449711 322953216 78450 18446744073709551615 4194304 6238623 140733433702816 140733433699368 4635239 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/16874/statm: 78846 78450 264 500 0 78343 0
[pid=16875] ppid=16856 vsize=22040 CPUtime=0.02
/proc/16875/stat : 16875 (parse.py) S 16856 16856 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 119449711 22568960 1128 18446744073709551615 4194304 6642060 140735504477024 140735504475384 139702227568416 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/16875/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.09
Current children cumulated vsize (KiB) 346636

Child status: 0
Real time (s): 302.642
CPU time (s): 300.147
CPU user time (s): 298.971
CPU system time (s): 1.17607
CPU usage (%): 99.1757
Max. virtual memory (cumulated for all children) (KiB): 456916

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.971
system time used= 1.17607
maximum resident set size= 397252
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 222354
page faults= 6
swaps= 0
block input operations= 42592
block output operations= 46840
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 85
involuntary context switches= 34396

runsolver used 0.568035 second user time and 1.21608 second system time

The end