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/201108241238/packup2mp4tr-0.6/rand149.cudf.s-e-l-s.log.runsolver ./packup2mp4tr-0.6 /home/misc2010/data/2011/incremental/s-e-l-s/rand149.cudf /home/misc2010/tmp/201108241238/packup2mp4tr-0.6/rand149.cudf.s-e-l-s.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.02 1.03 0.87 5/34 2431
/proc/meminfo: memFree=746668/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) R 2429 2430 1511 34817 1511 4202496 361 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=4104 CPUtime=0
/proc/2431/stat : 2431 (packup) R 2430 2430 1511 34817 1511 4202496 507 0 0 0 0 0 0 0 25 0 1 0 747127 4202496 435 1283457024 134512640 134752139 4293288032 18446744073709551615 134681869 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/2431/statm: 1026 435 286 59 0 190 0

[startup+0.18341 s]
/proc/loadavg: 1.02 1.03 0.87 5/34 2431
/proc/meminfo: memFree=746668/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=10788 CPUtime=0.18
/proc/2431/stat : 2431 (packup) R 2430 2430 1511 34817 1511 4202496 2198 0 0 0 18 0 0 0 25 0 1 0 747127 11046912 2126 1283457024 134512640 134752139 4293288032 18446744073709551615 134681863 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/2431/statm: 2697 2126 286 59 0 1861 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 13360

[startup+0.213414 s]
/proc/loadavg: 1.02 1.03 0.87 5/34 2431
/proc/meminfo: memFree=746668/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=11844 CPUtime=0.2
/proc/2431/stat : 2431 (packup) R 2430 2430 1511 34817 1511 4202496 2448 0 0 0 20 0 0 0 25 0 1 0 747127 12128256 2376 1283457024 134512640 134752139 4293288032 18446744073709551615 134682016 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/2431/statm: 2961 2376 286 59 0 2125 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 14416

[startup+0.303424 s]
/proc/loadavg: 1.02 1.03 0.87 5/34 2431
/proc/meminfo: memFree=746668/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=14680 CPUtime=0.3
/proc/2431/stat : 2431 (packup) R 2430 2430 1511 34817 1511 4202496 3165 0 0 0 30 0 0 0 25 0 1 0 747127 15032320 3093 1283457024 134512640 134752139 4293288032 18446744073709551615 134681682 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/2431/statm: 3670 3093 286 59 0 2834 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 17252

[startup+0.703509 s]
/proc/loadavg: 1.02 1.03 0.87 5/34 2431
/proc/meminfo: memFree=746668/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=26244 CPUtime=0.69
/proc/2431/stat : 2431 (packup) R 2430 2430 1511 34817 1511 4202496 6037 0 0 0 68 1 0 0 25 0 1 0 747127 26873856 5965 1283457024 134512640 134752139 4293288032 18446744073709551615 134682011 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/2431/statm: 6561 5965 286 59 0 5725 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 28816

[startup+1.50365 s]
/proc/loadavg: 1.02 1.03 0.87 2/35 2432
/proc/meminfo: memFree=713672/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=52716 CPUtime=1.5
/proc/2431/stat : 2431 (packup) R 2430 2430 1511 34817 1511 4202496 13019 0 0 0 146 4 0 0 25 0 1 0 747127 53981184 12607 1283457024 134512640 134752139 4293288032 18446744073709551615 4157543853 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/2431/statm: 13179 12607 306 59 0 12343 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 55288

[startup+3.10382 s]
/proc/loadavg: 1.02 1.03 0.87 2/35 2432
/proc/meminfo: memFree=679944/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=67852 CPUtime=2.22
/proc/2431/stat : 2431 (packup) S 2430 2430 1511 34817 1511 4202496 16835 0 0 0 187 35 0 0 25 0 1 0 747127 69480448 16068 1283457024 134512640 134752139 4293288032 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/2431/statm: 16963 16068 325 59 0 16127 0
Current children cumulated CPU time (s) 2.22
Current children cumulated vsize (KiB) 70424
heavy processes:

[startup+6.30511 s]
/proc/loadavg: 1.02 1.03 0.87 2/35 2434
/proc/meminfo: memFree=680688/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=67856 CPUtime=5.66
/proc/2431/stat : 2431 (packup) S 2430 2430 1511 34817 1511 4202496 16940 18593 0 0 218 55 262 31 19 0 1 0 747127 69484544 16087 1283457024 134512640 134752139 4293288032 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/2431/statm: 16964 16087 333 59 0 16128 0
Current children cumulated CPU time (s) 5.66
Current children cumulated vsize (KiB) 70428

[startup+12.707 s]
/proc/loadavg: 1.02 1.03 0.87 2/37 2436
/proc/meminfo: memFree=527152/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=67856 CPUtime=5.66
/proc/2431/stat : 2431 (packup) S 2430 2430 1511 34817 1511 4202496 16940 18593 0 0 218 55 262 31 19 0 1 0 747127 69484544 16087 1283457024 134512640 134752139 4293288032 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/2431/statm: 16964 16087 333 59 0 16128 0
[pid=2435] ppid=2431 vsize=1676 CPUtime=0
/proc/2435/stat : 2435 (sh) S 2431 2430 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 20 0 1 0 747695 1716224 124 1283457024 134512640 134593992 4289914320 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/2435/statm: 419 124 108 20 0 46 0
[pid=2436] ppid=2435 vsize=163624 CPUtime=7
/proc/2436/stat : 2436 (minisatp_32) R 2435 2430 1511 34817 1511 4202496 54031 0 0 0 655 45 0 0 25 0 1 0 747696 167550976 38093 1283457024 134512640 135413687 4294349360 18446744073709551615 134971908 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/2436/statm: 40906 38093 107 220 0 40684 0
Current children cumulated CPU time (s) 12.66
Current children cumulated vsize (KiB) 235728

[startup+25.5102 s]
/proc/loadavg: 1.01 1.02 0.87 2/37 2440
/proc/meminfo: memFree=646812/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=67864 CPUtime=23.74
/proc/2431/stat : 2431 (packup) S 2430 2430 1511 34817 1511 4202496 17168 132892 0 0 267 110 1867 130 18 0 1 0 747127 69492736 16100 1283457024 134512640 134752139 4293288032 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/2431/statm: 16966 16100 333 59 0 16130 0
[pid=2439] ppid=2431 vsize=1672 CPUtime=0
/proc/2439/stat : 2439 (sh) S 2431 2430 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 18 0 1 0 749507 1712128 124 1283457024 134512640 134593992 4291225360 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/2439/statm: 418 124 108 20 0 45 0
[pid=2440] ppid=2439 vsize=41160 CPUtime=1.69
/proc/2440/stat : 2440 (minisatp_32) R 2439 2430 1511 34817 1511 4202496 9870 0 0 0 165 4 0 0 25 0 1 0 749508 42147840 8904 1283457024 134512640 135413687 4294519376 18446744073709551615 134967004 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/2440/statm: 10290 8904 77 220 0 10068 0
Current children cumulated CPU time (s) 25.43
Current children cumulated vsize (KiB) 113268

[startup+51.1081 s]
/proc/loadavg: 1.01 1.02 0.87 2/37 2440
/proc/meminfo: memFree=359008/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=67864 CPUtime=23.74
/proc/2431/stat : 2431 (packup) S 2430 2430 1511 34817 1511 4202496 17168 132892 0 0 267 110 1867 130 18 0 1 0 747127 69492736 16100 1283457024 134512640 134752139 4293288032 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/2431/statm: 16966 16100 333 59 0 16130 0
[pid=2439] ppid=2431 vsize=1672 CPUtime=0
/proc/2439/stat : 2439 (sh) S 2431 2430 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 18 0 1 0 749507 1712128 124 1283457024 134512640 134593992 4291225360 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/2439/statm: 418 124 108 20 0 45 0
[pid=2440] ppid=2439 vsize=358580 CPUtime=27.27
/proc/2440/stat : 2440 (minisatp_32) R 2439 2430 1511 34817 1511 4202496 130038 0 0 0 2648 79 0 0 25 0 1 0 749508 367185920 85092 1283457024 134512640 135413687 4294519376 18446744073709551615 134524576 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/2440/statm: 89645 85092 110 220 0 89423 0
Current children cumulated CPU time (s) 51.01
Current children cumulated vsize (KiB) 430688

[startup+102.307 s]
/proc/loadavg: 1.00 1.02 0.88 2/37 2440
/proc/meminfo: memFree=238976/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=67864 CPUtime=23.74
/proc/2431/stat : 2431 (packup) S 2430 2430 1511 34817 1511 4202496 17168 132892 0 0 267 110 1867 130 18 0 1 0 747127 69492736 16100 1283457024 134512640 134752139 4293288032 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/2431/statm: 16966 16100 333 59 0 16130 0
[pid=2439] ppid=2431 vsize=1672 CPUtime=0
/proc/2439/stat : 2439 (sh) S 2431 2430 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 18 0 1 0 749507 1712128 124 1283457024 134512640 134593992 4291225360 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/2439/statm: 418 124 108 20 0 45 0
[pid=2440] ppid=2439 vsize=469480 CPUtime=78.46
/proc/2440/stat : 2440 (minisatp_32) R 2439 2430 1511 34817 1511 4202496 185123 0 0 0 7736 110 0 0 25 0 1 0 749508 480747520 109538 1283457024 134512640 135413687 4294519376 18446744073709551615 134649456 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/2440/statm: 117370 109538 110 220 0 117148 0
Current children cumulated CPU time (s) 102.2
Current children cumulated vsize (KiB) 541588

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

[startup+102.407 s]
/proc/loadavg: 1.00 1.02 0.88 2/37 2440
/proc/meminfo: memFree=238976/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=67864 CPUtime=23.74
/proc/2431/stat : 2431 (packup) S 2430 2430 1511 34817 1511 4202496 17168 132892 0 0 267 110 1867 130 18 0 1 0 747127 69492736 16100 1283457024 134512640 134752139 4293288032 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/2431/statm: 16966 16100 333 59 0 16130 0
[pid=2439] ppid=2431 vsize=1672 CPUtime=0
/proc/2439/stat : 2439 (sh) S 2431 2430 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 18 0 1 0 749507 1712128 124 1283457024 134512640 134593992 4291225360 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/2439/statm: 418 124 108 20 0 45 0
[pid=2440] ppid=2439 vsize=469480 CPUtime=78.56
/proc/2440/stat : 2440 (minisatp_32) R 2439 2430 1511 34817 1511 4202496 185123 0 0 0 7746 110 0 0 25 0 1 0 749508 480747520 109538 1283457024 134512640 135413687 4294519376 18446744073709551615 134649683 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/2440/statm: 117370 109538 110 220 0 117148 0
Current children cumulated CPU time (s) 102.3
Current children cumulated vsize (KiB) 541588

[startup+115.211 s]
/proc/loadavg: 1.00 1.02 0.88 2/37 2440
/proc/meminfo: memFree=238852/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=67864 CPUtime=23.74
/proc/2431/stat : 2431 (packup) S 2430 2430 1511 34817 1511 4202496 17168 132892 0 0 267 110 1867 130 18 0 1 0 747127 69492736 16100 1283457024 134512640 134752139 4293288032 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/2431/statm: 16966 16100 333 59 0 16130 0
[pid=2439] ppid=2431 vsize=1672 CPUtime=0
/proc/2439/stat : 2439 (sh) S 2431 2430 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 18 0 1 0 749507 1712128 124 1283457024 134512640 134593992 4291225360 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/2439/statm: 418 124 108 20 0 45 0
[pid=2440] ppid=2439 vsize=469480 CPUtime=91.35
/proc/2440/stat : 2440 (minisatp_32) R 2439 2430 1511 34817 1511 4202496 185230 0 0 0 9025 110 0 0 25 0 1 0 749508 480747520 109642 1283457024 134512640 135413687 4294519376 18446744073709551615 134649535 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/2440/statm: 117370 109642 110 220 0 117148 0
Current children cumulated CPU time (s) 115.09
Current children cumulated vsize (KiB) 541588

[startup+128.005 s]
/proc/loadavg: 1.00 1.02 0.88 2/37 2440
/proc/meminfo: memFree=237364/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=67864 CPUtime=23.74
/proc/2431/stat : 2431 (packup) S 2430 2430 1511 34817 1511 4202496 17168 132892 0 0 267 110 1867 130 18 0 1 0 747127 69492736 16100 1283457024 134512640 134752139 4293288032 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/2431/statm: 16966 16100 333 59 0 16130 0
[pid=2439] ppid=2431 vsize=1672 CPUtime=0
/proc/2439/stat : 2439 (sh) S 2431 2430 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 18 0 1 0 749507 1712128 124 1283457024 134512640 134593992 4291225360 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/2439/statm: 418 124 108 20 0 45 0
[pid=2440] ppid=2439 vsize=469972 CPUtime=104.13
/proc/2440/stat : 2440 (minisatp_32) R 2439 2430 1511 34817 1511 4202496 186021 0 0 0 10303 110 0 0 25 0 1 0 749508 481251328 109868 1283457024 134512640 135413687 4294519376 18446744073709551615 134649535 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/2440/statm: 117493 109868 110 220 0 117271 0
Current children cumulated CPU time (s) 127.87
Current children cumulated vsize (KiB) 542080

[startup+131.206 s]
/proc/loadavg: 1.00 1.01 0.88 2/37 2440
/proc/meminfo: memFree=237364/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=67864 CPUtime=23.74
/proc/2431/stat : 2431 (packup) S 2430 2430 1511 34817 1511 4202496 17168 132892 0 0 267 110 1867 130 18 0 1 0 747127 69492736 16100 1283457024 134512640 134752139 4293288032 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/2431/statm: 16966 16100 333 59 0 16130 0
[pid=2439] ppid=2431 vsize=1672 CPUtime=0
/proc/2439/stat : 2439 (sh) S 2431 2430 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 18 0 1 0 749507 1712128 124 1283457024 134512640 134593992 4291225360 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/2439/statm: 418 124 108 20 0 45 0
[pid=2440] ppid=2439 vsize=469972 CPUtime=107.33
/proc/2440/stat : 2440 (minisatp_32) R 2439 2430 1511 34817 1511 4202496 186049 0 0 0 10623 110 0 0 25 0 1 0 749508 481251328 109895 1283457024 134512640 135413687 4294519376 18446744073709551615 134650365 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/2440/statm: 117493 109895 110 220 0 117271 0
Current children cumulated CPU time (s) 131.07
Current children cumulated vsize (KiB) 542080

[startup+132.806 s]
/proc/loadavg: 1.00 1.01 0.88 2/37 2440
/proc/meminfo: memFree=237240/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=67864 CPUtime=23.74
/proc/2431/stat : 2431 (packup) S 2430 2430 1511 34817 1511 4202496 17168 132892 0 0 267 110 1867 130 18 0 1 0 747127 69492736 16100 1283457024 134512640 134752139 4293288032 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/2431/statm: 16966 16100 333 59 0 16130 0
[pid=2439] ppid=2431 vsize=1672 CPUtime=0
/proc/2439/stat : 2439 (sh) S 2431 2430 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 18 0 1 0 749507 1712128 124 1283457024 134512640 134593992 4291225360 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/2439/statm: 418 124 108 20 0 45 0
[pid=2440] ppid=2439 vsize=469972 CPUtime=108.93
/proc/2440/stat : 2440 (minisatp_32) R 2439 2430 1511 34817 1511 4202496 186579 0 0 0 10783 110 0 0 25 0 1 0 749508 481251328 109907 1283457024 134512640 135413687 4294519376 18446744073709551615 134650344 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/2440/statm: 117493 109907 110 220 0 117271 0
Current children cumulated CPU time (s) 132.67
Current children cumulated vsize (KiB) 542080

[startup+134.407 s]
/proc/loadavg: 1.00 1.01 0.88 2/37 2440
/proc/meminfo: memFree=237116/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=67864 CPUtime=23.74
/proc/2431/stat : 2431 (packup) S 2430 2430 1511 34817 1511 4202496 17168 132892 0 0 267 110 1867 130 18 0 1 0 747127 69492736 16100 1283457024 134512640 134752139 4293288032 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/2431/statm: 16966 16100 333 59 0 16130 0
[pid=2439] ppid=2431 vsize=1672 CPUtime=0
/proc/2439/stat : 2439 (sh) S 2431 2430 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 18 0 1 0 749507 1712128 124 1283457024 134512640 134593992 4291225360 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/2439/statm: 418 124 108 20 0 45 0
[pid=2440] ppid=2439 vsize=469972 CPUtime=110.53
/proc/2440/stat : 2440 (minisatp_32) R 2439 2430 1511 34817 1511 4202496 187107 0 0 0 10943 110 0 0 25 0 1 0 749508 481251328 109918 1283457024 134512640 135413687 4294519376 18446744073709551615 134649574 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/2440/statm: 117493 109918 110 220 0 117271 0
Current children cumulated CPU time (s) 134.27
Current children cumulated vsize (KiB) 542080

[startup+135.207 s]
/proc/loadavg: 1.00 1.01 0.88 2/37 2440
/proc/meminfo: memFree=237116/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=67864 CPUtime=23.74
/proc/2431/stat : 2431 (packup) S 2430 2430 1511 34817 1511 4202496 17168 132892 0 0 267 110 1867 130 18 0 1 0 747127 69492736 16100 1283457024 134512640 134752139 4293288032 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/2431/statm: 16966 16100 333 59 0 16130 0
[pid=2439] ppid=2431 vsize=1672 CPUtime=0
/proc/2439/stat : 2439 (sh) S 2431 2430 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 18 0 1 0 749507 1712128 124 1283457024 134512640 134593992 4291225360 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/2439/statm: 418 124 108 20 0 45 0
[pid=2440] ppid=2439 vsize=447096 CPUtime=111.34
/proc/2440/stat : 2440 (minisatp_32) R 2439 2430 1511 34817 1511 4202496 187613 0 0 0 11022 112 0 0 25 0 1 0 749508 457826304 104796 1283457024 134512640 135413687 4294519376 18446744073709551615 134597339 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/2440/statm: 111774 104796 118 220 0 111552 0
Current children cumulated CPU time (s) 135.08
Current children cumulated vsize (KiB) 519204

[startup+135.408 s]
/proc/loadavg: 1.00 1.01 0.88 2/37 2440
/proc/meminfo: memFree=257452/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=67868 CPUtime=135.3
/proc/2431/stat : 2431 (packup) R 2430 2430 1511 34817 1511 4202496 21349 320655 0 0 269 112 12901 248 18 0 1 0 747127 69496832 16114 1283457024 134512640 134752139 4293288032 18446744073709551615 134525484 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/2431/statm: 16967 16114 346 59 0 16131 0
Current children cumulated CPU time (s) 135.3
Current children cumulated vsize (KiB) 70440

[startup+135.508 s]
/proc/loadavg: 1.00 1.01 0.88 2/37 2440
/proc/meminfo: memFree=257452/1048576 swapFree=0/0
[pid=2430] ppid=2429 vsize=2572 CPUtime=0
/proc/2430/stat : 2430 (packup2mp4tr-0.) S 2429 2430 1511 34817 1511 4202496 379 0 0 0 0 0 0 0 25 0 1 0 747127 2633728 275 1283457024 134512640 135304128 4288390112 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/2430/statm: 643 275 233 194 0 30 0
[pid=2431] ppid=2430 vsize=66128 CPUtime=135.4
/proc/2431/stat : 2431 (packup) R 2430 2430 1511 34817 1511 4202496 30302 320655 0 0 279 112 12901 248 18 0 1 0 747127 67715072 15679 1283457024 134512640 134752139 4293288032 18446744073709551615 134536317 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/2431/statm: 16532 15679 346 59 0 15696 0
Current children cumulated CPU time (s) 135.4
Current children cumulated vsize (KiB) 68700

Child status: 0
Real time (s): 135.553
CPU time (s): 135.456
CPU user time (s): 131.84
CPU system time (s): 3.61623
CPU usage (%): 99.9287
Max. virtual memory (cumulated for all children) (KiB): 590296

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 131.84
system time used= 3.61623
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 352880
page faults= 0
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 20
involuntary context switches= 1729

runsolver used 0 second user time and 0.012 second system time

The end