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/upgrade/difficult/rand131.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/difficult/rand131.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/upgrade/difficult/rand131.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.87 0.94 0.97 2/60 26836
/proc/meminfo: memFree=285424/1022884 swapFree=0/0
[pid=26836] ppid=26835 vsize=9204 CPUtime=0
/proc/26836/stat : 26836 (aspcud-full) S 26835 26836 32685 0 -1 4202496 431 0 0 0 0 0 0 0 20 0 1 0 42221312 9424896 331 18446744073709551615 4194304 5129932 140737301914816 140737301912280 140483946956576 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/26836/statm: 2301 331 272 229 0 61 0

[startup+0.129907 s]
/proc/loadavg: 0.87 0.94 0.97 2/60 26836
/proc/meminfo: memFree=285424/1022884 swapFree=0/0
[pid=26836] ppid=26835 vsize=9212 CPUtime=0.04
/proc/26836/stat : 26836 (aspcud-full) S 26835 26836 32685 0 -1 4202496 741 3624 0 0 0 0 4 0 20 0 1 0 42221312 9433088 364 18446744073709551615 4194304 5129932 140737301914816 140737301913472 140483946812510 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26836/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200311 s]
/proc/loadavg: 0.87 0.94 0.97 2/60 26836
/proc/meminfo: memFree=285424/1022884 swapFree=0/0
[pid=26836] ppid=26835 vsize=9212 CPUtime=0.04
/proc/26836/stat : 26836 (aspcud-full) S 26835 26836 32685 0 -1 4202496 741 3624 0 0 0 0 4 0 20 0 1 0 42221312 9433088 364 18446744073709551615 4194304 5129932 140737301914816 140737301913472 140483946812510 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26836/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300305 s]
/proc/loadavg: 0.87 0.94 0.97 2/60 26836
/proc/meminfo: memFree=285424/1022884 swapFree=0/0
[pid=26836] ppid=26835 vsize=9212 CPUtime=0.04
/proc/26836/stat : 26836 (aspcud-full) S 26835 26836 32685 0 -1 4202496 741 3624 0 0 0 0 4 0 20 0 1 0 42221312 9433088 364 18446744073709551615 4194304 5129932 140737301914816 140737301913472 140483946812510 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26836/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700214 s]
/proc/loadavg: 0.87 0.94 0.97 2/60 26836
/proc/meminfo: memFree=285424/1022884 swapFree=0/0
[pid=26836] ppid=26835 vsize=9212 CPUtime=0.04
/proc/26836/stat : 26836 (aspcud-full) S 26835 26836 32685 0 -1 4202496 741 3624 0 0 0 0 4 0 20 0 1 0 42221312 9433088 364 18446744073709551615 4194304 5129932 140737301914816 140737301913472 140483946812510 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26836/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 0.87 0.94 0.97 2/62 26852
/proc/meminfo: memFree=250680/1022884 swapFree=0/0
[pid=26836] ppid=26835 vsize=9212 CPUtime=0.04
/proc/26836/stat : 26836 (aspcud-full) S 26835 26836 32685 0 -1 4202496 741 3624 0 0 0 0 4 0 20 0 1 0 42221312 9433088 364 18446744073709551615 4194304 5129932 140737301914816 140737301913472 140483946812510 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26836/statm: 2303 364 303 229 0 63 0
[pid=26852] ppid=26836 vsize=57336 CPUtime=1.41
/proc/26852/stat : 26852 (cudf2lp) R 26836 26836 32685 0 -1 4202496 14153 0 0 0 133 8 0 0 20 0 1 0 42221316 58712064 12419 18446744073709551615 4194304 5690517 140735678103376 140735678099544 4956096 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/26852/statm: 14334 12419 160 366 0 13965 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 66548

[startup+3.10031 s]
/proc/loadavg: 0.87 0.94 0.97 2/62 26852
/proc/meminfo: memFree=218440/1022884 swapFree=0/0
[pid=26836] ppid=26835 vsize=9212 CPUtime=0.04
/proc/26836/stat : 26836 (aspcud-full) S 26835 26836 32685 0 -1 4202496 741 3624 0 0 0 0 4 0 20 0 1 0 42221312 9433088 364 18446744073709551615 4194304 5129932 140737301914816 140737301913472 140483946812510 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26836/statm: 2303 364 303 229 0 63 0
[pid=26852] ppid=26836 vsize=93028 CPUtime=2.96
/proc/26852/stat : 26852 (cudf2lp) R 26836 26836 32685 0 -1 4202496 26566 0 0 0 282 14 0 0 20 0 1 0 42221316 95260672 19838 18446744073709551615 4194304 5690517 140735678103376 140735678101016 4356879 0 0 16781316 0 0 0 0 17 0 0 0 7 0 0
/proc/26852/statm: 23257 19838 160 366 0 22888 0
Current children cumulated CPU time (s) 3
Current children cumulated vsize (KiB) 102240

[startup+6.30025 s]
/proc/loadavg: 0.88 0.94 0.97 2/62 26853
/proc/meminfo: memFree=203388/1022884 swapFree=0/0
[pid=26836] ppid=26835 vsize=9212 CPUtime=4.5
/proc/26836/stat : 26836 (aspcud-full) S 26835 26836 32685 0 -1 4202496 766 42947 0 0 0 0 425 25 20 0 1 0 42221312 9433088 364 18446744073709551615 4194304 5129932 140737301914816 140737301913472 140483946812510 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26836/statm: 2303 364 303 229 0 63 0
[pid=26853] ppid=26836 vsize=113212 CPUtime=1.68
/proc/26853/stat : 26853 (gringo) R 26836 26836 32685 0 -1 4202496 30394 0 0 0 160 8 0 0 20 0 1 0 42221773 115929088 25211 18446744073709551615 4194304 6531320 140735801713392 140735801709736 4360328 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/26853/statm: 28303 25211 280 571 0 27724 0
Current children cumulated CPU time (s) 6.18
Current children cumulated vsize (KiB) 122424

[startup+12.7003 s]
/proc/loadavg: 0.89 0.94 0.97 2/63 26855
/proc/meminfo: memFree=286704/1022884 swapFree=0/0
[pid=26836] ppid=26835 vsize=9212 CPUtime=9.84
/proc/26836/stat : 26836 (aspcud-full) S 26835 26836 32685 0 -1 4202496 803 159143 0 0 0 0 916 68 20 0 1 0 42221312 9433088 364 18446744073709551615 4194304 5129932 140737301914816 140737301912880 140483946812510 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26836/statm: 2303 364 303 229 0 63 0
[pid=26854] ppid=26836 vsize=150660 CPUtime=2.5
/proc/26854/stat : 26854 (clasp) R 26836 26836 32685 0 -1 4202496 45518 0 1 0 238 12 0 0 20 0 1 0 42222324 154275840 37180 18446744073709551615 4194304 6238623 140734115440672 140734115437696 4669508 0 0 16781316 18946 0 0 0 17 0 0 0 3 0 0
/proc/26854/statm: 37665 37180 263 500 0 37162 0
[pid=26855] ppid=26836 vsize=22040 CPUtime=0.01
/proc/26855/stat : 26855 (parse.py) S 26836 26836 32685 0 -1 4202496 1309 0 10 0 1 0 0 0 20 0 1 0 42222324 22568960 1129 18446744073709551615 4194304 6642060 140736002515024 140736002513384 140724450051872 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/26855/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 12.35
Current children cumulated vsize (KiB) 181912

[startup+25.5003 s]
/proc/loadavg: 0.91 0.94 0.97 2/63 26855
/proc/meminfo: memFree=286704/1022884 swapFree=0/0
[pid=26836] ppid=26835 vsize=9212 CPUtime=9.84
/proc/26836/stat : 26836 (aspcud-full) S 26835 26836 32685 0 -1 4202496 803 159143 0 0 0 0 916 68 20 0 1 0 42221312 9433088 364 18446744073709551615 4194304 5129932 140737301914816 140737301912880 140483946812510 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26836/statm: 2303 364 303 229 0 63 0
[pid=26854] ppid=26836 vsize=150660 CPUtime=15.23
/proc/26854/stat : 26854 (clasp) R 26836 26836 32685 0 -1 4202496 45566 0 1 0 1511 12 0 0 20 0 1 0 42222324 154275840 37228 18446744073709551615 4194304 6238623 140734115440672 140734115437696 4676771 0 0 16781316 18946 0 0 0 17 0 0 0 3 0 0
/proc/26854/statm: 37665 37228 263 500 0 37162 0
[pid=26855] ppid=26836 vsize=22040 CPUtime=0.01
/proc/26855/stat : 26855 (parse.py) S 26836 26836 32685 0 -1 4202496 1309 0 10 0 1 0 0 0 20 0 1 0 42222324 22568960 1129 18446744073709551615 4194304 6642060 140736002515024 140736002513384 140724450051872 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/26855/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 25.08
Current children cumulated vsize (KiB) 181912

[startup+51.1004 s]
/proc/loadavg: 0.94 0.95 0.97 2/63 26855
/proc/meminfo: memFree=286704/1022884 swapFree=0/0
[pid=26836] ppid=26835 vsize=9212 CPUtime=9.84
/proc/26836/stat : 26836 (aspcud-full) S 26835 26836 32685 0 -1 4202496 803 159143 0 0 0 0 916 68 20 0 1 0 42221312 9433088 364 18446744073709551615 4194304 5129932 140737301914816 140737301912880 140483946812510 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26836/statm: 2303 364 303 229 0 63 0
[pid=26854] ppid=26836 vsize=150660 CPUtime=40.68
/proc/26854/stat : 26854 (clasp) R 26836 26836 32685 0 -1 4202496 45566 0 1 0 4055 13 0 0 20 0 1 0 42222324 154275840 37228 18446744073709551615 4194304 6238623 140734115440672 140734115437696 4586298 0 0 16781316 18946 0 0 0 17 0 0 0 3 0 0
/proc/26854/statm: 37665 37228 263 500 0 37162 0
[pid=26855] ppid=26836 vsize=22040 CPUtime=0.01
/proc/26855/stat : 26855 (parse.py) S 26836 26836 32685 0 -1 4202496 1309 0 10 0 1 0 0 0 20 0 1 0 42222324 22568960 1129 18446744073709551615 4194304 6642060 140736002515024 140736002513384 140724450051872 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/26855/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 50.53
Current children cumulated vsize (KiB) 181912

[startup+102.3 s]
/proc/loadavg: 0.97 0.95 0.97 2/63 26855
/proc/meminfo: memFree=286208/1022884 swapFree=0/0
[pid=26836] ppid=26835 vsize=9212 CPUtime=9.84
/proc/26836/stat : 26836 (aspcud-full) S 26835 26836 32685 0 -1 4202496 803 159143 0 0 0 0 916 68 20 0 1 0 42221312 9433088 364 18446744073709551615 4194304 5129932 140737301914816 140737301912880 140483946812510 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26836/statm: 2303 364 303 229 0 63 0
[pid=26854] ppid=26836 vsize=150660 CPUtime=91.6
/proc/26854/stat : 26854 (clasp) R 26836 26836 32685 0 -1 4202496 45700 0 1 0 9146 14 0 0 20 0 1 0 42222324 154275840 37362 18446744073709551615 4194304 6238623 140734115440672 140734115437696 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 3 0 0
/proc/26854/statm: 37665 37362 263 500 0 37162 0
[pid=26855] ppid=26836 vsize=22040 CPUtime=0.01
/proc/26855/stat : 26855 (parse.py) S 26836 26836 32685 0 -1 4202496 1309 0 10 0 1 0 0 0 20 0 1 0 42222324 22568960 1129 18446744073709551615 4194304 6642060 140736002515024 140736002513384 140724450051872 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/26855/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 101.45
Current children cumulated vsize (KiB) 181912

[startup+162.3 s]
/proc/loadavg: 0.99 0.96 0.97 2/63 26855
/proc/meminfo: memFree=241940/1022884 swapFree=0/0
[pid=26836] ppid=26835 vsize=9212 CPUtime=9.84
/proc/26836/stat : 26836 (aspcud-full) S 26835 26836 32685 0 -1 4202496 803 159143 0 0 0 0 916 68 20 0 1 0 42221312 9433088 364 18446744073709551615 4194304 5129932 140737301914816 140737301912880 140483946812510 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26836/statm: 2303 364 303 229 0 63 0
[pid=26854] ppid=26836 vsize=197024 CPUtime=151.28
/proc/26854/stat : 26854 (clasp) R 26836 26836 32685 0 -1 4202496 56734 0 1 0 15107 21 0 0 20 0 1 0 42222324 201752576 48396 18446744073709551615 4194304 6238623 140734115440672 140734115437696 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 3 0 0
/proc/26854/statm: 49256 48396 263 500 0 48753 0
[pid=26855] ppid=26836 vsize=22040 CPUtime=0.01
/proc/26855/stat : 26855 (parse.py) S 26836 26836 32685 0 -1 4202496 1309 0 10 0 1 0 0 0 20 0 1 0 42222324 22568960 1129 18446744073709551615 4194304 6642060 140736002515024 140736002513384 140724450051872 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/26855/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 161.13
Current children cumulated vsize (KiB) 228276

[startup+222.308 s]
/proc/loadavg: 0.99 0.96 0.97 2/63 26855
/proc/meminfo: memFree=222224/1022884 swapFree=0/0
[pid=26836] ppid=26835 vsize=9212 CPUtime=9.84
/proc/26836/stat : 26836 (aspcud-full) S 26835 26836 32685 0 -1 4202496 803 159143 0 0 0 0 916 68 20 0 1 0 42221312 9433088 364 18446744073709551615 4194304 5129932 140737301914816 140737301912880 140483946812510 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26836/statm: 2303 364 303 229 0 63 0
[pid=26854] ppid=26836 vsize=215880 CPUtime=210.95
/proc/26854/stat : 26854 (clasp) R 26836 26836 32685 0 -1 4202496 61762 0 1 0 21070 25 0 0 20 0 1 0 42222324 221061120 53424 18446744073709551615 4194304 6238623 140734115440672 140734115437224 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 3 0 0
/proc/26854/statm: 53970 53424 263 500 0 53467 0
[pid=26855] ppid=26836 vsize=22040 CPUtime=0.01
/proc/26855/stat : 26855 (parse.py) S 26836 26836 32685 0 -1 4202496 1309 0 10 0 1 0 0 0 20 0 1 0 42222324 22568960 1129 18446744073709551615 4194304 6642060 140736002515024 140736002513384 140724450051872 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/26855/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 220.8
Current children cumulated vsize (KiB) 247132

[startup+282.3 s]
/proc/loadavg: 0.99 0.97 0.97 2/63 26855
/proc/meminfo: memFree=190108/1022884 swapFree=0/0
[pid=26836] ppid=26835 vsize=9212 CPUtime=9.84
/proc/26836/stat : 26836 (aspcud-full) S 26835 26836 32685 0 -1 4202496 803 159143 0 0 0 0 916 68 20 0 1 0 42221312 9433088 364 18446744073709551615 4194304 5129932 140737301914816 140737301912880 140483946812510 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26836/statm: 2303 364 303 229 0 63 0
[pid=26854] ppid=26836 vsize=246696 CPUtime=270.63
/proc/26854/stat : 26854 (clasp) R 26836 26836 32685 0 -1 4202496 69675 0 1 0 27031 32 0 0 20 0 1 0 42222324 252616704 61337 18446744073709551615 4194304 6238623 140734115440672 140734115437696 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 3 0 0
/proc/26854/statm: 61674 61337 263 500 0 61171 0
[pid=26855] ppid=26836 vsize=22040 CPUtime=0.01
/proc/26855/stat : 26855 (parse.py) S 26836 26836 32685 0 -1 4202496 1309 0 10 0 1 0 0 0 20 0 1 0 42222324 22568960 1129 18446744073709551615 4194304 6642060 140736002515024 140736002513384 140724450051872 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/26855/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 280.48
Current children cumulated vsize (KiB) 277948



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302 s]
/proc/loadavg: 0.99 0.97 0.97 2/63 26855
/proc/meminfo: memFree=162084/1022884 swapFree=0/0
[pid=26836] ppid=26835 vsize=9212 CPUtime=9.84
/proc/26836/stat : 26836 (aspcud-full) S 26835 26836 32685 0 -1 4202496 803 159143 0 0 0 0 916 68 20 0 1 0 42221312 9433088 364 18446744073709551615 4194304 5129932 140737301914816 140737301912880 140483946812510 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26836/statm: 2303 364 303 229 0 63 0
[pid=26854] ppid=26836 vsize=274916 CPUtime=290.22
/proc/26854/stat : 26854 (clasp) R 26836 26836 32685 0 -1 4202496 76673 0 1 0 28987 35 0 0 20 0 1 0 42222324 281513984 68335 18446744073709551615 4194304 6238623 140734115440672 140734115437696 4409890 0 0 16781316 18946 0 0 0 17 0 0 0 3 0 0
/proc/26854/statm: 68729 68335 263 500 0 68226 0
[pid=26855] ppid=26836 vsize=22040 CPUtime=0.01
/proc/26855/stat : 26855 (parse.py) S 26836 26836 32685 0 -1 4202496 1309 0 10 0 1 0 0 0 20 0 1 0 42222324 22568960 1129 18446744073709551615 4194304 6642060 140736002515024 140736002513384 140724450051872 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/26855/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 300.07
Current children cumulated vsize (KiB) 306168

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 s]
/proc/loadavg: 0.99 0.97 0.97 2/63 26855
/proc/meminfo: memFree=162084/1022884 swapFree=0/0
[pid=26836] ppid=26835 vsize=9212 CPUtime=9.84
/proc/26836/stat : 26836 (aspcud-full) S 26835 26836 32685 0 -1 4202496 803 159143 0 0 0 0 916 68 20 0 1 0 42221312 9433088 364 18446744073709551615 4194304 5129932 140737301914816 140737301912880 140483946812510 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26836/statm: 2303 364 303 229 0 63 0
[pid=26854] ppid=26836 vsize=274916 CPUtime=290.22
/proc/26854/stat : 26854 (clasp) R 26836 26836 32685 0 -1 4202496 76673 0 1 0 28987 35 0 0 20 0 1 0 42222324 281513984 68335 18446744073709551615 4194304 6238623 140734115440672 140734115437696 4409890 0 0 16781316 18946 0 0 0 17 0 0 0 3 0 0
/proc/26854/statm: 68729 68335 263 500 0 68226 0
[pid=26855] ppid=26836 vsize=22040 CPUtime=0.01
/proc/26855/stat : 26855 (parse.py) S 26836 26836 32685 0 -1 4202496 1309 0 10 0 1 0 0 0 20 0 1 0 42222324 22568960 1129 18446744073709551615 4194304 6642060 140736002515024 140736002513384 140724450051872 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/26855/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 300.07
Current children cumulated vsize (KiB) 306168

Child status: 0
Real time (s): 302.071
CPU time (s): 300.151
CPU user time (s): 299.063
CPU system time (s): 1.08807
CPU usage (%): 99.3642
Max. virtual memory (cumulated for all children) (KiB): 495048

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.063
system time used= 1.08807
maximum resident set size= 427648
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 238243
page faults= 12
swaps= 0
block input operations= 69704
block output operations= 53760
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 104
involuntary context switches= 5162

runsolver used 0.496031 second user time and 1.15607 second system time

The end