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/201108281254/packup2hy4tr-0.6/rand529.cudf.s.log.runsolver ./packup2hy4tr-0.6 /home/misc2010/data/2011/incremental/s/rand529.cudf /home/misc2010/tmp/201108281254/packup2hy4tr-0.6/rand529.cudf.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.03 1.01 0.95 3/37 19397
/proc/meminfo: memFree=318728/1048576 swapFree=0/0
[pid=19396] ppid=19395 vsize=2568 CPUtime=0
/proc/19396/stat : 19396 (packup2hy4tr-0.) S 19395 19396 17551 34817 17551 4202496 379 0 0 0 0 0 0 0 18 0 1 0 35577520 2629632 274 1283457024 134512640 135304128 4290430432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/19396/statm: 642 274 233 194 0 29 0
[pid=19397] ppid=19396 vsize=3712 CPUtime=0
/proc/19397/stat : 19397 (packup) D 19396 19396 17551 34817 17551 4202496 389 0 0 0 0 0 0 0 18 0 1 0 35577520 3801088 317 1283457024 134512640 134752139 4289680640 18446744073709551615 4294960130 0 0 18944 8192 18446744071564332000 0 0 17 0 0 0 0
/proc/19397/statm: 928 317 273 59 0 92 0

[startup+0.190508 s]
/proc/loadavg: 1.03 1.01 0.95 3/37 19397
/proc/meminfo: memFree=318728/1048576 swapFree=0/0
[pid=19396] ppid=19395 vsize=2568 CPUtime=0
/proc/19396/stat : 19396 (packup2hy4tr-0.) S 19395 19396 17551 34817 17551 4202496 379 0 0 0 0 0 0 0 18 0 1 0 35577520 2629632 274 1283457024 134512640 135304128 4290430432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/19396/statm: 642 274 233 194 0 29 0
[pid=19397] ppid=19396 vsize=9836 CPUtime=0.17
/proc/19397/stat : 19397 (packup) R 19396 19396 17551 34817 17551 4202496 1937 0 0 0 16 1 0 0 25 0 1 0 35577520 10072064 1865 1283457024 134512640 134752139 4289680640 18446744073709551615 134681805 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/19397/statm: 2459 1865 286 59 0 1623 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 12404

[startup+0.206509 s]
/proc/loadavg: 1.03 1.01 0.95 3/37 19397
/proc/meminfo: memFree=318728/1048576 swapFree=0/0
[pid=19396] ppid=19395 vsize=2568 CPUtime=0
/proc/19396/stat : 19396 (packup2hy4tr-0.) S 19395 19396 17551 34817 17551 4202496 379 0 0 0 0 0 0 0 18 0 1 0 35577520 2629632 274 1283457024 134512640 135304128 4290430432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/19396/statm: 642 274 233 194 0 29 0
[pid=19397] ppid=19396 vsize=10184 CPUtime=0.17
/proc/19397/stat : 19397 (packup) R 19396 19396 17551 34817 17551 4202496 2051 0 0 0 16 1 0 0 25 0 1 0 35577520 10428416 1979 1283457024 134512640 134752139 4289680640 18446744073709551615 134694895 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/19397/statm: 2546 1979 286 59 0 1710 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 12752

[startup+0.315655 s]
/proc/loadavg: 1.03 1.01 0.95 3/37 19397
/proc/meminfo: memFree=318728/1048576 swapFree=0/0
[pid=19396] ppid=19395 vsize=2568 CPUtime=0
/proc/19396/stat : 19396 (packup2hy4tr-0.) S 19395 19396 17551 34817 17551 4202496 379 0 0 0 0 0 0 0 18 0 1 0 35577520 2629632 274 1283457024 134512640 135304128 4290430432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/19396/statm: 642 274 233 194 0 29 0
[pid=19397] ppid=19396 vsize=14780 CPUtime=0.28
/proc/19397/stat : 19397 (packup) R 19396 19396 17551 34817 17551 4202496 3232 0 0 0 26 2 0 0 25 0 1 0 35577520 15134720 3160 1283457024 134512640 134752139 4289680640 18446744073709551615 4294960130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/19397/statm: 3695 3160 321 59 0 2859 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 17348

[startup+0.715723 s]
/proc/loadavg: 1.03 1.01 0.95 3/37 19397
/proc/meminfo: memFree=318728/1048576 swapFree=0/0
[pid=19396] ppid=19395 vsize=2568 CPUtime=0
/proc/19396/stat : 19396 (packup2hy4tr-0.) S 19395 19396 17551 34817 17551 4202496 379 0 0 0 0 0 0 0 18 0 1 0 35577520 2629632 274 1283457024 134512640 135304128 4290430432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/19396/statm: 642 274 233 194 0 29 0
[pid=19397] ppid=19396 vsize=15356 CPUtime=0.55
/proc/19397/stat : 19397 (packup) S 19396 19396 17551 34817 17551 4202496 3474 2091 0 0 29 10 16 0 24 0 1 0 35577520 15724544 3247 1283457024 134512640 134752139 4289680640 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/19397/statm: 3839 3247 332 59 0 3003 0
Current children cumulated CPU time (s) 0.55
Current children cumulated vsize (KiB) 17924

[startup+1.51586 s]
/proc/loadavg: 1.03 1.01 0.95 2/41 19416
/proc/meminfo: memFree=290968/1048576 swapFree=0/0
[pid=19396] ppid=19395 vsize=2568 CPUtime=0
/proc/19396/stat : 19396 (packup2hy4tr-0.) S 19395 19396 17551 34817 17551 4202496 379 0 0 0 0 0 0 0 18 0 1 0 35577520 2629632 274 1283457024 134512640 135304128 4290430432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/19396/statm: 642 274 233 194 0 29 0
[pid=19397] ppid=19396 vsize=15360 CPUtime=0.78
/proc/19397/stat : 19397 (packup) S 19396 19396 17551 34817 17551 4202496 3509 4283 0 0 32 14 30 2 24 0 1 0 35577520 15728640 3248 1283457024 134512640 134752139 4289680640 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/19397/statm: 3840 3248 332 59 0 3004 0
[pid=19411] ppid=19397 vsize=1672 CPUtime=0
/proc/19411/stat : 19411 (sh) S 19397 19396 17551 34817 17551 4202496 145 0 0 0 0 0 0 0 24 0 1 0 35577603 1712128 123 1283457024 134512640 134593992 4286646976 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/19411/statm: 418 123 108 20 0 45 0
[pid=19412] ppid=19411 vsize=2576 CPUtime=0
/proc/19412/stat : 19412 (run_h) S 19411 19396 17551 34817 17551 4202496 368 611 0 0 0 0 0 0 25 0 1 0 35577604 2637824 274 1283457024 134512640 135304128 4291479408 18446744073709551615 4294960130 0 65536 18948 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19412/statm: 644 274 232 194 0 31 0
[pid=19416] ppid=19412 vsize=13144 CPUtime=0.68
/proc/19416/stat : 19416 (minisatp_32) R 19412 19396 17551 34817 17551 4202496 4543 0 0 0 66 2 0 0 25 0 1 0 35577604 13459456 2816 1283457024 134512640 135413687 4288291936 18446744073709551615 134649535 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/19416/statm: 3286 2816 109 220 0 3064 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 35320

[startup+3.10618 s]
/proc/loadavg: 1.03 1.01 0.95 2/41 19416
/proc/meminfo: memFree=290348/1048576 swapFree=0/0
[pid=19396] ppid=19395 vsize=2568 CPUtime=0
/proc/19396/stat : 19396 (packup2hy4tr-0.) S 19395 19396 17551 34817 17551 4202496 379 0 0 0 0 0 0 0 18 0 1 0 35577520 2629632 274 1283457024 134512640 135304128 4290430432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/19396/statm: 642 274 233 194 0 29 0
[pid=19397] ppid=19396 vsize=15360 CPUtime=0.78
/proc/19397/stat : 19397 (packup) S 19396 19396 17551 34817 17551 4202496 3509 4283 0 0 32 14 30 2 24 0 1 0 35577520 15728640 3248 1283457024 134512640 134752139 4289680640 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/19397/statm: 3840 3248 332 59 0 3004 0
[pid=19411] ppid=19397 vsize=1672 CPUtime=0
/proc/19411/stat : 19411 (sh) S 19397 19396 17551 34817 17551 4202496 145 0 0 0 0 0 0 0 24 0 1 0 35577603 1712128 123 1283457024 134512640 134593992 4286646976 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/19411/statm: 418 123 108 20 0 45 0
[pid=19412] ppid=19411 vsize=2576 CPUtime=0
/proc/19412/stat : 19412 (run_h) S 19411 19396 17551 34817 17551 4202496 368 611 0 0 0 0 0 0 25 0 1 0 35577604 2637824 274 1283457024 134512640 135304128 4291479408 18446744073709551615 4294960130 0 65536 18948 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19412/statm: 644 274 232 194 0 31 0
[pid=19416] ppid=19412 vsize=15516 CPUtime=2.26
/proc/19416/stat : 19416 (minisatp_32) R 19412 19396 17551 34817 17551 4202496 5059 0 0 0 224 2 0 0 25 0 1 0 35577604 15888384 3249 1283457024 134512640 135413687 4288291936 18446744073709551615 134649456 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/19416/statm: 3879 3249 109 220 0 3657 0
Current children cumulated CPU time (s) 3.04
Current children cumulated vsize (KiB) 37692

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

[startup+3.2062 s]
/proc/loadavg: 1.03 1.01 0.95 2/41 19416
/proc/meminfo: memFree=290348/1048576 swapFree=0/0
[pid=19396] ppid=19395 vsize=2568 CPUtime=0
/proc/19396/stat : 19396 (packup2hy4tr-0.) S 19395 19396 17551 34817 17551 4202496 379 0 0 0 0 0 0 0 18 0 1 0 35577520 2629632 274 1283457024 134512640 135304128 4290430432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/19396/statm: 642 274 233 194 0 29 0
[pid=19397] ppid=19396 vsize=15360 CPUtime=0.78
/proc/19397/stat : 19397 (packup) S 19396 19396 17551 34817 17551 4202496 3509 4283 0 0 32 14 30 2 24 0 1 0 35577520 15728640 3248 1283457024 134512640 134752139 4289680640 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/19397/statm: 3840 3248 332 59 0 3004 0
[pid=19411] ppid=19397 vsize=1672 CPUtime=0
/proc/19411/stat : 19411 (sh) S 19397 19396 17551 34817 17551 4202496 145 0 0 0 0 0 0 0 24 0 1 0 35577603 1712128 123 1283457024 134512640 134593992 4286646976 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/19411/statm: 418 123 108 20 0 45 0
[pid=19412] ppid=19411 vsize=2576 CPUtime=0
/proc/19412/stat : 19412 (run_h) S 19411 19396 17551 34817 17551 4202496 368 611 0 0 0 0 0 0 25 0 1 0 35577604 2637824 274 1283457024 134512640 135304128 4291479408 18446744073709551615 4294960130 0 65536 18948 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19412/statm: 644 274 232 194 0 31 0
[pid=19416] ppid=19412 vsize=15516 CPUtime=2.36
/proc/19416/stat : 19416 (minisatp_32) R 19412 19396 17551 34817 17551 4202496 5079 0 0 0 234 2 0 0 25 0 1 0 35577604 15888384 3268 1283457024 134512640 135413687 4288291936 18446744073709551615 134649673 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/19416/statm: 3879 3268 109 220 0 3657 0
Current children cumulated CPU time (s) 3.14
Current children cumulated vsize (KiB) 37692

[startup+3.60627 s]
/proc/loadavg: 1.03 1.01 0.95 2/41 19416
/proc/meminfo: memFree=289356/1048576 swapFree=0/0
[pid=19396] ppid=19395 vsize=2568 CPUtime=0
/proc/19396/stat : 19396 (packup2hy4tr-0.) S 19395 19396 17551 34817 17551 4202496 379 0 0 0 0 0 0 0 18 0 1 0 35577520 2629632 274 1283457024 134512640 135304128 4290430432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/19396/statm: 642 274 233 194 0 29 0
[pid=19397] ppid=19396 vsize=15360 CPUtime=0.78
/proc/19397/stat : 19397 (packup) S 19396 19396 17551 34817 17551 4202496 3509 4283 0 0 32 14 30 2 24 0 1 0 35577520 15728640 3248 1283457024 134512640 134752139 4289680640 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/19397/statm: 3840 3248 332 59 0 3004 0
[pid=19411] ppid=19397 vsize=1672 CPUtime=0
/proc/19411/stat : 19411 (sh) S 19397 19396 17551 34817 17551 4202496 145 0 0 0 0 0 0 0 24 0 1 0 35577603 1712128 123 1283457024 134512640 134593992 4286646976 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/19411/statm: 418 123 108 20 0 45 0
[pid=19412] ppid=19411 vsize=2576 CPUtime=0
/proc/19412/stat : 19412 (run_h) S 19411 19396 17551 34817 17551 4202496 368 611 0 0 0 0 0 0 25 0 1 0 35577604 2637824 274 1283457024 134512640 135304128 4291479408 18446744073709551615 4294960130 0 65536 18948 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19412/statm: 644 274 232 194 0 31 0
[pid=19416] ppid=19412 vsize=15516 CPUtime=2.76
/proc/19416/stat : 19416 (minisatp_32) R 19412 19396 17551 34817 17551 4202496 5173 0 0 0 274 2 0 0 25 0 1 0 35577604 15888384 3355 1283457024 134512640 135413687 4288291936 18446744073709551615 134649535 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/19416/statm: 3879 3355 109 220 0 3657 0
Current children cumulated CPU time (s) 3.54
Current children cumulated vsize (KiB) 37692

[startup+4.00634 s]
/proc/loadavg: 1.03 1.01 0.95 2/41 19416
/proc/meminfo: memFree=289356/1048576 swapFree=0/0
[pid=19396] ppid=19395 vsize=2568 CPUtime=0
/proc/19396/stat : 19396 (packup2hy4tr-0.) S 19395 19396 17551 34817 17551 4202496 379 0 0 0 0 0 0 0 18 0 1 0 35577520 2629632 274 1283457024 134512640 135304128 4290430432 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/19396/statm: 642 274 233 194 0 29 0
[pid=19397] ppid=19396 vsize=15360 CPUtime=0.78
/proc/19397/stat : 19397 (packup) S 19396 19396 17551 34817 17551 4202496 3509 4283 0 0 32 14 30 2 24 0 1 0 35577520 15728640 3248 1283457024 134512640 134752139 4289680640 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/19397/statm: 3840 3248 332 59 0 3004 0
[pid=19411] ppid=19397 vsize=1672 CPUtime=0
/proc/19411/stat : 19411 (sh) S 19397 19396 17551 34817 17551 4202496 145 0 0 0 0 0 0 0 24 0 1 0 35577603 1712128 123 1283457024 134512640 134593992 4286646976 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/19411/statm: 418 123 108 20 0 45 0
[pid=19412] ppid=19411 vsize=2576 CPUtime=0
/proc/19412/stat : 19412 (run_h) S 19411 19396 17551 34817 17551 4202496 368 611 0 0 0 0 0 0 25 0 1 0 35577604 2637824 274 1283457024 134512640 135304128 4291479408 18446744073709551615 4294960130 0 65536 18948 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19412/statm: 644 274 232 194 0 31 0
[pid=19416] ppid=19412 vsize=15660 CPUtime=3.16
/proc/19416/stat : 19416 (minisatp_32) R 19412 19396 17551 34817 17551 4202496 5286 0 0 0 314 2 0 0 25 0 1 0 35577604 16035840 3442 1283457024 134512640 135413687 4288291936 18446744073709551615 134649586 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/19416/statm: 3915 3442 109 220 0 3693 0
Current children cumulated CPU time (s) 3.94
Current children cumulated vsize (KiB) 37836

Child status: 0
Real time (s): 4.09664
CPU time (s): 4.06825
CPU user time (s): 3.85624
CPU system time (s): 0.212013
CPU usage (%): 99.3072
Max. virtual memory (cumulated for all children) (KiB): 37836

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.85624
system time used= 0.212013
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 17739
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= 46
involuntary context switches= 120

runsolver used 0 second user time and 0 second system time

The end