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/d5026b8e-3477-11e0-986e-00163e3d3b7c.cudf.dudf-real.log.runsolver ./packup2hy4tr-0.6 /home/misc2010/data/2011/dudf-real//d5026b8e-3477-11e0-986e-00163e3d3b7c.cudf /home/misc2010/tmp/201108281254/packup2hy4tr-0.6/d5026b8e-3477-11e0-986e-00163e3d3b7c.cudf.dudf-real.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.04 1.00 3/39 23847
/proc/meminfo: memFree=227776/1048576 swapFree=0/0
[pid=23846] ppid=23845 vsize=2572 CPUtime=0
/proc/23846/stat : 23846 (packup2hy4tr-0.) S 23845 23846 17551 34817 17551 4202496 377 0 0 0 0 0 0 0 18 0 1 0 36041416 2633728 274 1283457024 134512640 135304128 4293757136 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23846/statm: 643 274 233 194 0 30 0
[pid=23847] ppid=23846 vsize=3712 CPUtime=0
/proc/23847/stat : 23847 (packup) D 23846 23846 17551 34817 17551 4202496 388 0 0 0 0 0 0 0 18 0 1 0 36041416 3801088 317 1283457024 134512640 134752139 4291798736 18446744073709551615 4294960130 0 0 18944 8192 18446744071564332000 0 0 17 0 0 0 0
/proc/23847/statm: 928 317 273 59 0 92 0

[startup+0.199152 s]
/proc/loadavg: 1.03 1.04 1.00 3/39 23847
/proc/meminfo: memFree=227776/1048576 swapFree=0/0
[pid=23846] ppid=23845 vsize=2572 CPUtime=0
/proc/23846/stat : 23846 (packup2hy4tr-0.) S 23845 23846 17551 34817 17551 4202496 377 0 0 0 0 0 0 0 18 0 1 0 36041416 2633728 274 1283457024 134512640 135304128 4293757136 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23846/statm: 643 274 233 194 0 30 0
[pid=23847] ppid=23846 vsize=9908 CPUtime=0.15
/proc/23847/stat : 23847 (packup) R 23846 23846 17551 34817 17551 4202496 1959 0 0 0 14 1 0 0 25 0 1 0 36041416 10145792 1888 1283457024 134512640 134752139 4291798736 18446744073709551615 4159198484 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/23847/statm: 2477 1888 286 59 0 1641 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 12480

[startup+0.207092 s]
/proc/loadavg: 1.03 1.04 1.00 3/39 23847
/proc/meminfo: memFree=227776/1048576 swapFree=0/0
[pid=23846] ppid=23845 vsize=2572 CPUtime=0
/proc/23846/stat : 23846 (packup2hy4tr-0.) S 23845 23846 17551 34817 17551 4202496 377 0 0 0 0 0 0 0 18 0 1 0 36041416 2633728 274 1283457024 134512640 135304128 4293757136 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23846/statm: 643 274 233 194 0 30 0
[pid=23847] ppid=23846 vsize=10040 CPUtime=0.16
/proc/23847/stat : 23847 (packup) R 23846 23846 17551 34817 17551 4202496 2013 0 0 0 15 1 0 0 25 0 1 0 36041416 10280960 1942 1283457024 134512640 134752139 4291798736 18446744073709551615 4157774643 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/23847/statm: 2510 1942 286 59 0 1674 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 12612

[startup+0.307096 s]
/proc/loadavg: 1.03 1.04 1.00 3/39 23847
/proc/meminfo: memFree=227776/1048576 swapFree=0/0
[pid=23846] ppid=23845 vsize=2572 CPUtime=0
/proc/23846/stat : 23846 (packup2hy4tr-0.) S 23845 23846 17551 34817 17551 4202496 377 0 0 0 0 0 0 0 18 0 1 0 36041416 2633728 274 1283457024 134512640 135304128 4293757136 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23846/statm: 643 274 233 194 0 30 0
[pid=23847] ppid=23846 vsize=13020 CPUtime=0.25
/proc/23847/stat : 23847 (packup) R 23846 23846 17551 34817 17551 4202496 2731 0 0 0 23 2 0 0 25 0 1 0 36041416 13332480 2660 1283457024 134512640 134752139 4291798736 18446744073709551615 134682079 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/23847/statm: 3255 2660 286 59 0 2419 0
Current children cumulated CPU time (s) 0.25
Current children cumulated vsize (KiB) 15592

[startup+0.703132 s]
/proc/loadavg: 1.03 1.04 1.00 3/39 23847
/proc/meminfo: memFree=227776/1048576 swapFree=0/0
[pid=23846] ppid=23845 vsize=2572 CPUtime=0
/proc/23846/stat : 23846 (packup2hy4tr-0.) S 23845 23846 17551 34817 17551 4202496 377 0 0 0 0 0 0 0 18 0 1 0 36041416 2633728 274 1283457024 134512640 135304128 4293757136 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23846/statm: 643 274 233 194 0 30 0
[pid=23847] ppid=23846 vsize=23116 CPUtime=0.61
/proc/23847/stat : 23847 (packup) R 23846 23846 17551 34817 17551 4202496 5273 0 0 0 56 5 0 0 25 0 1 0 36041416 23670784 5202 1283457024 134512640 134752139 4291798736 18446744073709551615 134683169 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/23847/statm: 5779 5202 286 59 0 4943 0
Current children cumulated CPU time (s) 0.61
Current children cumulated vsize (KiB) 25688

[startup+1.51586 s]
/proc/loadavg: 1.03 1.04 1.00 2/43 23854
/proc/meminfo: memFree=182140/1048576 swapFree=0/0
[pid=23846] ppid=23845 vsize=2572 CPUtime=0
/proc/23846/stat : 23846 (packup2hy4tr-0.) S 23845 23846 17551 34817 17551 4202496 377 0 0 0 0 0 0 0 18 0 1 0 36041416 2633728 274 1283457024 134512640 135304128 4293757136 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23846/statm: 643 274 233 194 0 30 0
[pid=23847] ppid=23846 vsize=31912 CPUtime=1.41
/proc/23847/stat : 23847 (packup) R 23846 23846 17551 34817 17551 4202496 7750 3932 0 0 78 16 40 7 21 0 1 0 36041416 32677888 7355 1283457024 134512640 134752139 4291798736 18446744073709551615 4294960130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/23847/statm: 7978 7355 332 59 0 7142 0
Current children cumulated CPU time (s) 1.41
Current children cumulated vsize (KiB) 34484

[startup+3.10625 s]
/proc/loadavg: 1.03 1.04 1.00 2/43 23860
/proc/meminfo: memFree=169244/1048576 swapFree=0/0
[pid=23846] ppid=23845 vsize=2572 CPUtime=0
/proc/23846/stat : 23846 (packup2hy4tr-0.) S 23845 23846 17551 34817 17551 4202496 377 0 0 0 0 0 0 0 18 0 1 0 36041416 2633728 274 1283457024 134512640 135304128 4293757136 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23846/statm: 643 274 233 194 0 30 0
[pid=23847] ppid=23846 vsize=31920 CPUtime=2.96
/proc/23847/stat : 23847 (packup) S 23846 23846 17551 34817 17551 4202496 7855 14388 0 0 92 41 148 15 16 0 1 0 36041416 32686080 7361 1283457024 134512640 134752139 4291798736 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/23847/statm: 7980 7361 332 59 0 7144 0
Current children cumulated CPU time (s) 2.96
Current children cumulated vsize (KiB) 34492

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

[startup+3.20626 s]
/proc/loadavg: 1.03 1.04 1.00 2/43 23860
/proc/meminfo: memFree=169244/1048576 swapFree=0/0
[pid=23846] ppid=23845 vsize=2572 CPUtime=0
/proc/23846/stat : 23846 (packup2hy4tr-0.) S 23845 23846 17551 34817 17551 4202496 377 0 0 0 0 0 0 0 18 0 1 0 36041416 2633728 274 1283457024 134512640 135304128 4293757136 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23846/statm: 643 274 233 194 0 30 0
[pid=23847] ppid=23846 vsize=31920 CPUtime=2.96
/proc/23847/stat : 23847 (packup) S 23846 23846 17551 34817 17551 4202496 7855 14388 0 0 92 41 148 15 16 0 1 0 36041416 32686080 7361 1283457024 134512640 134752139 4291798736 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/23847/statm: 7980 7361 332 59 0 7144 0
Current children cumulated CPU time (s) 2.96
Current children cumulated vsize (KiB) 34492

[startup+4.0089 s]
/proc/loadavg: 1.03 1.04 1.00 3/45 23877
/proc/meminfo: memFree=165988/1048576 swapFree=0/0
[pid=23846] ppid=23845 vsize=2572 CPUtime=0
/proc/23846/stat : 23846 (packup2hy4tr-0.) S 23845 23846 17551 34817 17551 4202496 377 0 0 0 0 0 0 0 18 0 1 0 36041416 2633728 274 1283457024 134512640 135304128 4293757136 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23846/statm: 643 274 233 194 0 30 0
[pid=23847] ppid=23846 vsize=31920 CPUtime=2.96
/proc/23847/stat : 23847 (packup) S 23846 23846 17551 34817 17551 4202496 7855 14388 0 0 92 41 148 15 16 0 1 0 36041416 32686080 7361 1283457024 134512640 134752139 4291798736 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/23847/statm: 7980 7361 332 59 0 7144 0
[pid=23867] ppid=23847 vsize=1672 CPUtime=0
/proc/23867/stat : 23867 (sh) S 23847 23846 17551 34817 17551 4202496 145 0 0 0 0 0 0 0 16 0 1 0 36041723 1712128 123 1283457024 134512640 134593992 4294941360 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/23867/statm: 418 123 108 20 0 45 0
[pid=23868] ppid=23867 vsize=2572 CPUtime=0
/proc/23868/stat : 23868 (run_h) S 23867 23846 17551 34817 17551 4202496 368 609 0 0 0 0 0 0 19 0 1 0 36041723 2633728 273 1283457024 134512640 135304128 4286575312 18446744073709551615 4294960130 0 65536 18948 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/23868/statm: 643 273 232 194 0 30 0
[pid=23872] ppid=23868 vsize=2564 CPUtime=0.01
/proc/23872/stat : 23872 (run_scip) S 23868 23846 17551 34817 17551 4202496 390 754 0 0 0 0 0 1 20 0 1 0 36041724 2625536 267 1283457024 134512640 135304128 4291342160 18446744073709551615 4294960130 0 65536 18948 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/23872/statm: 641 267 228 194 0 28 0
[pid=23876] ppid=23872 vsize=58168 CPUtime=0.9
/proc/23876/stat : 23876 (scip-2.0.1.linu) R 23872 23846 17551 34817 17551 4202496 15730 0 0 0 70 20 0 0 25 0 1 0 36041724 59564032 12603 1283457024 134512640 143279753 4294263248 18446744073709551615 135014673 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/23876/statm: 14542 12603 762 2141 0 12398 0
[pid=23877] ppid=23872 vsize=7192 CPUtime=0.01
/proc/23877/stat : 23877 (scip2v) S 23872 23846 17551 34817 17551 4202496 1008 0 0 0 1 0 0 0 18 0 1 0 36041737 7364608 847 1283457024 134512640 136477024 4288765168 18446744073709551615 4294960130 0 0 16800256 2 18446744071564457842 0 0 17 0 0 0 0
/proc/23877/statm: 1798 847 474 480 0 383 0
Current children cumulated CPU time (s) 3.88
Current children cumulated vsize (KiB) 106660

[startup+4.20896 s]
/proc/loadavg: 1.03 1.04 1.00 3/45 23877
/proc/meminfo: memFree=165988/1048576 swapFree=0/0
[pid=23846] ppid=23845 vsize=2572 CPUtime=0
/proc/23846/stat : 23846 (packup2hy4tr-0.) S 23845 23846 17551 34817 17551 4202496 377 0 0 0 0 0 0 0 18 0 1 0 36041416 2633728 274 1283457024 134512640 135304128 4293757136 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23846/statm: 643 274 233 194 0 30 0
[pid=23847] ppid=23846 vsize=31920 CPUtime=2.96
/proc/23847/stat : 23847 (packup) S 23846 23846 17551 34817 17551 4202496 7855 14388 0 0 92 41 148 15 16 0 1 0 36041416 32686080 7361 1283457024 134512640 134752139 4291798736 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/23847/statm: 7980 7361 332 59 0 7144 0
[pid=23867] ppid=23847 vsize=1672 CPUtime=0
/proc/23867/stat : 23867 (sh) S 23847 23846 17551 34817 17551 4202496 145 0 0 0 0 0 0 0 16 0 1 0 36041723 1712128 123 1283457024 134512640 134593992 4294941360 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/23867/statm: 418 123 108 20 0 45 0
[pid=23868] ppid=23867 vsize=2572 CPUtime=0
/proc/23868/stat : 23868 (run_h) R 23867 23846 17551 34817 17551 4202496 368 609 0 0 0 0 0 0 18 0 1 0 36041723 2633728 273 1283457024 134512640 135304128 4286575312 18446744073709551615 4294960130 0 65536 18948 65538 0 0 0 17 0 0 0 0
/proc/23868/statm: 643 273 232 194 0 30 0
[pid=23872] ppid=23868 vsize=0 CPUtime=1.11
/proc/23872/stat : 23872 (run_scip) Z 23868 23846 17551 34817 17551 4202508 402 17627 0 0 0 0 77 34 18 0 1 0 36041724 0 0 1283457024 0 0 0 0 0 0 0 18948 65536 18446744071564254338 0 0 17 0 0 0 0
/proc/23872/statm: 0 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.07
Current children cumulated vsize (KiB) 38736

Child status: 0
Real time (s): 4.30307
CPU time (s): 4.20426
CPU user time (s): 3.2562
CPU system time (s): 0.948059
CPU usage (%): 97.7039
Max. virtual memory (cumulated for all children) (KiB): 106840

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.2562
system time used= 0.948059
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 48529
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= 17353
involuntary context switches= 17394

runsolver used 0 second user time and 0 second system time

The end