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: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand81406f.cudf.impossible.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/2010/impossible//rand81406f.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand81406f.cudf.impossible.result 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 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.15 1.13 1.06 1/46 25105
/proc/meminfo: memFree=700900/1048576 swapFree=2075068/2097144
[pid=25105] ppid=25104 vsize=3024 CPUtime=0
/proc/25105/stat : 25105 (runsolver) R 25104 25105 4159 34819 4229 4202560 72 0 0 0 0 0 0 0 25 0 1 0 882553427 3096576 94 1283457024 134512640 134586868 4293574672 18446744073709551615 4294960130 0 0 0 24578 0 0 0 17 0 0 0 0
/proc/25105/statm: 756 94 62 19 0 54 0

[startup+0.192606 s]
/proc/loadavg: 1.15 1.13 1.06 1/46 25105
/proc/meminfo: memFree=700900/1048576 swapFree=2075068/2097144
[pid=25105] ppid=25104 vsize=2596 CPUtime=0
/proc/25105/stat : 25105 (aspcud-trendy-1) S 25104 25105 4159 34819 4229 4202496 619 2209 0 3 0 0 0 0 25 0 1 0 882553427 2658304 300 1283457024 134512640 135304128 4288164784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/25105/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.204643 s]
/proc/loadavg: 1.15 1.13 1.06 1/46 25105
/proc/meminfo: memFree=700900/1048576 swapFree=2075068/2097144
[pid=25105] ppid=25104 vsize=2596 CPUtime=0
/proc/25105/stat : 25105 (aspcud-trendy-1) S 25104 25105 4159 34819 4229 4202496 619 2209 0 3 0 0 0 0 25 0 1 0 882553427 2658304 300 1283457024 134512640 135304128 4288164784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/25105/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.503437 s]
/proc/loadavg: 1.15 1.13 1.06 1/46 25105
/proc/meminfo: memFree=700900/1048576 swapFree=2075068/2097144
[pid=25105] ppid=25104 vsize=2596 CPUtime=0
/proc/25105/stat : 25105 (aspcud-trendy-1) S 25104 25105 4159 34819 4229 4202496 619 2209 0 3 0 0 0 0 25 0 1 0 882553427 2658304 300 1283457024 134512640 135304128 4288164784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/25105/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.713314 s]
/proc/loadavg: 1.15 1.13 1.06 1/46 25105
/proc/meminfo: memFree=700900/1048576 swapFree=2075068/2097144
[pid=25105] ppid=25104 vsize=2596 CPUtime=0
/proc/25105/stat : 25105 (aspcud-trendy-1) S 25104 25105 4159 34819 4229 4202496 619 2209 0 3 0 0 0 0 25 0 1 0 882553427 2658304 300 1283457024 134512640 135304128 4288164784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/25105/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.5135 s]
/proc/loadavg: 1.15 1.13 1.06 2/50 25119
/proc/meminfo: memFree=661720/1048576 swapFree=2075068/2097144
[pid=25105] ppid=25104 vsize=2596 CPUtime=0
/proc/25105/stat : 25105 (aspcud-trendy-1) S 25104 25105 4159 34819 4229 4202496 619 2209 0 3 0 0 0 0 25 0 1 0 882553427 2658304 300 1283457024 134512640 135304128 4288164784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/25105/statm: 649 300 253 194 0 35 0
[pid=25117] ppid=25105 vsize=1868 CPUtime=0
/proc/25117/stat : 25117 (clasp) S 25105 25105 4159 34819 4229 4202496 270 0 15 0 0 0 0 0 23 0 1 0 882553431 1912832 153 1283457024 134512640 136223643 4293969040 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/25117/statm: 467 153 138 418 0 47 0
[pid=25118] ppid=25105 vsize=2604 CPUtime=0
/proc/25118/stat : 25118 (gringo) S 25105 25105 4159 34819 4229 4202496 384 0 23 0 0 0 0 0 23 0 1 0 882553431 2666496 276 1283457024 134512640 136959103 4288819696 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/25118/statm: 651 276 247 598 0 50 0
[pid=25119] ppid=25105 vsize=48104 CPUtime=1.26
/proc/25119/stat : 25119 (cudf2lp) R 25105 25105 4159 34819 4229 4202496 13352 0 14 0 122 4 0 0 25 0 1 0 882553431 49258496 11213 1283457024 134512640 135749571 4293343776 18446744073709551615 135187300 0 0 6 0 0 0 0 17 0 0 0 0
/proc/25119/statm: 12026 11213 127 302 0 11722 0
Current children cumulated CPU time (s) 1.26
Current children cumulated vsize (KiB) 55172

[startup+3.11411 s]
/proc/loadavg: 1.22 1.14 1.06 3/50 25119
/proc/meminfo: memFree=622976/1048576 swapFree=2075068/2097144
[pid=25105] ppid=25104 vsize=2596 CPUtime=0
/proc/25105/stat : 25105 (aspcud-trendy-1) S 25104 25105 4159 34819 4229 4202496 619 2209 0 3 0 0 0 0 25 0 1 0 882553427 2658304 300 1283457024 134512640 135304128 4288164784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/25105/statm: 649 300 253 194 0 35 0
[pid=25117] ppid=25105 vsize=17800 CPUtime=0.09
/proc/25117/stat : 25117 (clasp) S 25105 25105 4159 34819 4229 4202496 4864 0 18 0 7 2 0 0 18 0 1 0 882553431 18227200 4092 1283457024 134512640 136223643 4293969040 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/25117/statm: 4450 4092 174 418 0 4030 0
[pid=25118] ppid=25105 vsize=21484 CPUtime=0.8
/proc/25118/stat : 25118 (gringo) R 25105 25105 4159 34819 4229 4202496 6759 0 23 0 73 7 0 0 18 0 1 0 882553431 21999616 4608 1283457024 134512640 136959103 4288819696 18446744073709551615 134785596 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/25118/statm: 5371 4608 247 598 0 4770 0
[pid=25119] ppid=25105 vsize=62344 CPUtime=1.95
/proc/25119/stat : 25119 (cudf2lp) R 25105 25105 4159 34819 4229 4202496 18987 0 14 0 190 5 0 0 25 0 1 0 882553431 63840256 15186 1283457024 134512640 135749571 4293343776 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0
/proc/25119/statm: 15586 15186 129 302 0 15282 0
Current children cumulated CPU time (s) 2.84
Current children cumulated vsize (KiB) 104224

[startup+6.3073 s]
/proc/loadavg: 1.22 1.14 1.06 2/48 25119
/proc/meminfo: memFree=631504/1048576 swapFree=2075068/2097144
[pid=25105] ppid=25104 vsize=2596 CPUtime=4.65
/proc/25105/stat : 25105 (aspcud-trendy-1) S 25104 25105 4159 34819 4229 4202496 619 44452 0 41 0 0 444 21 18 0 1 0 882553427 2658304 300 1283457024 134512640 135304128 4288164784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/25105/statm: 649 300 253 194 0 35 0
[pid=25117] ppid=25105 vsize=69260 CPUtime=1.36
/proc/25117/stat : 25117 (clasp) R 25105 25105 4159 34819 4229 4202496 20085 0 19 0 127 9 0 0 19 0 1 0 882553431 70922240 15974 1283457024 134512640 136223643 4293969040 18446744073709551615 134878768 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/25117/statm: 17315 15974 214 418 0 16895 0
Current children cumulated CPU time (s) 6.01
Current children cumulated vsize (KiB) 71856

[startup+12.7092 s]
/proc/loadavg: 1.19 1.14 1.06 2/48 25119
/proc/meminfo: memFree=632992/1048576 swapFree=2075068/2097144
[pid=25105] ppid=25104 vsize=2596 CPUtime=4.65
/proc/25105/stat : 25105 (aspcud-trendy-1) S 25104 25105 4159 34819 4229 4202496 619 44452 0 41 0 0 444 21 18 0 1 0 882553427 2658304 300 1283457024 134512640 135304128 4288164784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/25105/statm: 649 300 253 194 0 35 0
[pid=25117] ppid=25105 vsize=68044 CPUtime=7.76
/proc/25117/stat : 25117 (clasp) R 25105 25105 4159 34819 4229 4202496 20128 0 19 0 766 10 0 0 25 0 1 0 882553431 69677056 15758 1283457024 134512640 136223643 4293969040 18446744073709551615 134924387 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/25117/statm: 17011 15758 225 418 0 16591 0
Current children cumulated CPU time (s) 12.41
Current children cumulated vsize (KiB) 70640

[startup+25.5031 s]
/proc/loadavg: 1.16 1.13 1.06 2/48 25119
/proc/meminfo: memFree=615136/1048576 swapFree=2075068/2097144
[pid=25105] ppid=25104 vsize=2596 CPUtime=4.65
/proc/25105/stat : 25105 (aspcud-trendy-1) S 25104 25105 4159 34819 4229 4202496 619 44452 0 41 0 0 444 21 18 0 1 0 882553427 2658304 300 1283457024 134512640 135304128 4288164784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/25105/statm: 649 300 253 194 0 35 0
[pid=25117] ppid=25105 vsize=86420 CPUtime=20.54
/proc/25117/stat : 25117 (clasp) R 25105 25105 4159 34819 4229 4202496 24709 0 19 0 2041 13 0 0 25 0 1 0 882553431 88494080 20339 1283457024 134512640 136223643 4293969040 18446744073709551615 134931000 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/25117/statm: 21605 20339 225 418 0 21185 0
Current children cumulated CPU time (s) 25.19
Current children cumulated vsize (KiB) 89016

[startup+51.1108 s]
/proc/loadavg: 1.10 1.12 1.06 2/49 25121
/proc/meminfo: memFree=590264/1048576 swapFree=2075136/2097144
[pid=25105] ppid=25104 vsize=2596 CPUtime=4.65
/proc/25105/stat : 25105 (aspcud-trendy-1) S 25104 25105 4159 34819 4229 4202496 619 44452 0 41 0 0 444 21 18 0 1 0 882553427 2658304 300 1283457024 134512640 135304128 4288164784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/25105/statm: 649 300 253 194 0 35 0
[pid=25117] ppid=25105 vsize=109904 CPUtime=46.1
/proc/25117/stat : 25117 (clasp) R 25105 25105 4159 34819 4229 4202496 30543 0 19 0 4591 19 0 0 25 0 1 0 882553431 112541696 26173 1283457024 134512640 136223643 4293969040 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/25117/statm: 27476 26173 225 418 0 27056 0
Current children cumulated CPU time (s) 50.75
Current children cumulated vsize (KiB) 112500

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

[startup+51.4109 s]
/proc/loadavg: 1.10 1.12 1.06 2/49 25121
/proc/meminfo: memFree=590264/1048576 swapFree=2075136/2097144
[pid=25105] ppid=25104 vsize=2596 CPUtime=4.65
/proc/25105/stat : 25105 (aspcud-trendy-1) S 25104 25105 4159 34819 4229 4202496 619 44452 0 41 0 0 444 21 18 0 1 0 882553427 2658304 300 1283457024 134512640 135304128 4288164784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/25105/statm: 649 300 253 194 0 35 0
[pid=25117] ppid=25105 vsize=109904 CPUtime=46.4
/proc/25117/stat : 25117 (clasp) R 25105 25105 4159 34819 4229 4202496 30543 0 19 0 4621 19 0 0 25 0 1 0 882553431 112541696 26173 1283457024 134512640 136223643 4293969040 18446744073709551615 134664705 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/25117/statm: 27476 26173 225 418 0 27056 0
Current children cumulated CPU time (s) 51.05
Current children cumulated vsize (KiB) 112500

[startup+77.0086 s]
/proc/loadavg: 1.07 1.11 1.05 2/49 25121
/proc/meminfo: memFree=581584/1048576 swapFree=2075136/2097144
[pid=25105] ppid=25104 vsize=2596 CPUtime=4.65
/proc/25105/stat : 25105 (aspcud-trendy-1) S 25104 25105 4159 34819 4229 4202496 619 44452 0 41 0 0 444 21 18 0 1 0 882553427 2658304 300 1283457024 134512640 135304128 4288164784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/25105/statm: 649 300 253 194 0 35 0
[pid=25117] ppid=25105 vsize=118556 CPUtime=72
/proc/25117/stat : 25117 (clasp) R 25105 25105 4159 34819 4229 4202496 32729 0 19 0 7179 21 0 0 25 0 1 0 882553431 121401344 28359 1283457024 134512640 136223643 4293969040 18446744073709551615 134928897 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/25117/statm: 29639 28359 225 418 0 29219 0
Current children cumulated CPU time (s) 76.65
Current children cumulated vsize (KiB) 121152

[startup+83.4102 s]
/proc/loadavg: 1.06 1.11 1.05 2/49 25121
/proc/meminfo: memFree=581460/1048576 swapFree=2075136/2097144
[pid=25105] ppid=25104 vsize=2596 CPUtime=4.65
/proc/25105/stat : 25105 (aspcud-trendy-1) S 25104 25105 4159 34819 4229 4202496 619 44452 0 41 0 0 444 21 18 0 1 0 882553427 2658304 300 1283457024 134512640 135304128 4288164784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/25105/statm: 649 300 253 194 0 35 0
[pid=25117] ppid=25105 vsize=118556 CPUtime=78.4
/proc/25117/stat : 25117 (clasp) R 25105 25105 4159 34819 4229 4202496 32729 0 19 0 7819 21 0 0 25 0 1 0 882553431 121401344 28359 1283457024 134512640 136223643 4293969040 18446744073709551615 134630084 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/25117/statm: 29639 28359 225 418 0 29219 0
Current children cumulated CPU time (s) 83.05
Current children cumulated vsize (KiB) 121152

[startup+86.6111 s]
/proc/loadavg: 1.06 1.11 1.05 2/49 25121
/proc/meminfo: memFree=576004/1048576 swapFree=2075136/2097144
[pid=25105] ppid=25104 vsize=2596 CPUtime=4.65
/proc/25105/stat : 25105 (aspcud-trendy-1) S 25104 25105 4159 34819 4229 4202496 619 44452 0 41 0 0 444 21 18 0 1 0 882553427 2658304 300 1283457024 134512640 135304128 4288164784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/25105/statm: 649 300 253 194 0 35 0
[pid=25117] ppid=25105 vsize=125948 CPUtime=81.58
/proc/25117/stat : 25117 (clasp) R 25105 25105 4159 34819 4229 4202496 34562 0 19 0 8136 22 0 0 25 0 1 0 882553431 128970752 30192 1283457024 134512640 136223643 4293969040 18446744073709551615 134664705 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/25117/statm: 31487 30192 225 418 0 31067 0
Current children cumulated CPU time (s) 86.23
Current children cumulated vsize (KiB) 128544

[startup+88.2116 s]
/proc/loadavg: 1.05 1.10 1.05 2/49 25121
/proc/meminfo: memFree=570052/1048576 swapFree=2075136/2097144
[pid=25105] ppid=25104 vsize=2596 CPUtime=4.65
/proc/25105/stat : 25105 (aspcud-trendy-1) S 25104 25105 4159 34819 4229 4202496 619 44452 0 41 0 0 444 21 18 0 1 0 882553427 2658304 300 1283457024 134512640 135304128 4288164784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/25105/statm: 649 300 253 194 0 35 0
[pid=25117] ppid=25105 vsize=130172 CPUtime=83.19
/proc/25117/stat : 25117 (clasp) R 25105 25105 4159 34819 4229 4202496 35622 0 19 0 8293 26 0 0 25 0 1 0 882553431 133296128 31252 1283457024 134512640 136223643 4293969040 18446744073709551615 134931064 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/25117/statm: 32543 31252 225 418 0 32123 0
Current children cumulated CPU time (s) 87.84
Current children cumulated vsize (KiB) 132768

[startup+89.0118 s]
/proc/loadavg: 1.05 1.10 1.05 2/49 25121
/proc/meminfo: memFree=570052/1048576 swapFree=2075136/2097144
[pid=25105] ppid=25104 vsize=2596 CPUtime=4.65
/proc/25105/stat : 25105 (aspcud-trendy-1) S 25104 25105 4159 34819 4229 4202496 619 44452 0 41 0 0 444 21 18 0 1 0 882553427 2658304 300 1283457024 134512640 135304128 4288164784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/25105/statm: 649 300 253 194 0 35 0
[pid=25117] ppid=25105 vsize=132284 CPUtime=83.99
/proc/25117/stat : 25117 (clasp) R 25105 25105 4159 34819 4229 4202496 36164 0 19 0 8373 26 0 0 25 0 1 0 882553431 135458816 31794 1283457024 134512640 136223643 4293969040 18446744073709551615 134712476 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/25117/statm: 33071 31794 225 418 0 32651 0
Current children cumulated CPU time (s) 88.64
Current children cumulated vsize (KiB) 134880

[startup+89.8121 s]
/proc/loadavg: 1.05 1.10 1.05 2/49 25121
/proc/meminfo: memFree=566952/1048576 swapFree=2075136/2097144
[pid=25105] ppid=25104 vsize=2596 CPUtime=4.65
/proc/25105/stat : 25105 (aspcud-trendy-1) S 25104 25105 4159 34819 4229 4202496 619 44452 0 41 0 0 444 21 18 0 1 0 882553427 2658304 300 1283457024 134512640 135304128 4288164784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/25105/statm: 649 300 253 194 0 35 0
[pid=25117] ppid=25105 vsize=134660 CPUtime=84.79
/proc/25117/stat : 25117 (clasp) R 25105 25105 4159 34819 4229 4202496 36755 0 19 0 8453 26 0 0 25 0 1 0 882553431 137891840 32385 1283457024 134512640 136223643 4293969040 18446744073709551615 134928992 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/25117/statm: 33665 32385 225 418 0 33245 0
Current children cumulated CPU time (s) 89.44
Current children cumulated vsize (KiB) 137256

[startup+90.0121 s]
/proc/loadavg: 1.05 1.10 1.05 2/49 25121
/proc/meminfo: memFree=566952/1048576 swapFree=2075136/2097144
[pid=25105] ppid=25104 vsize=2596 CPUtime=4.65
/proc/25105/stat : 25105 (aspcud-trendy-1) S 25104 25105 4159 34819 4229 4202496 619 44452 0 41 0 0 444 21 18 0 1 0 882553427 2658304 300 1283457024 134512640 135304128 4288164784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/25105/statm: 649 300 253 194 0 35 0
[pid=25117] ppid=25105 vsize=120116 CPUtime=84.99
/proc/25117/stat : 25117 (clasp) R 25105 25105 4159 34819 4229 4202496 36892 0 19 0 8473 26 0 0 25 0 1 0 882553431 122998784 29792 1283457024 134512640 136223643 4293969040 18446744073709551615 135599117 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/25117/statm: 30029 29792 231 418 0 29609 0
Current children cumulated CPU time (s) 89.64
Current children cumulated vsize (KiB) 122712

[startup+90.1022 s]
/proc/loadavg: 1.05 1.10 1.05 2/49 25121
/proc/meminfo: memFree=566952/1048576 swapFree=2075136/2097144
[pid=25105] ppid=25104 vsize=2700 CPUtime=89.69
/proc/25105/stat : 25105 (aspcud-trendy-1) S 25104 25105 4159 34819 4229 4202496 864 83346 0 61 0 0 8920 49 21 0 1 0 882553427 2764800 325 1283457024 134512640 135304128 4288164784 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0
/proc/25105/statm: 675 325 258 194 0 61 0
Current children cumulated CPU time (s) 89.69
Current children cumulated vsize (KiB) 2700

Child status: 0
Real time (s): 90.1147
CPU time (s): 89.7056
CPU user time (s): 89.2056
CPU system time (s): 0.500031
CPU usage (%): 99.546
Max. virtual memory (cumulated for all children) (KiB): 137652

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 89.2056
system time used= 0.500031
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 85574
page faults= 62
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 4024
involuntary context switches= 4329

runsolver used 0 second user time and 0.004 second system time

The end