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/bccf69ae-db9e-11df-9a24-00163e3d3b7c.cudf.dudf-real.log.runsolver ./packup2hy4tr-0.6 /home/misc2010/data/2011/dudf-real//bccf69ae-db9e-11df-9a24-00163e3d3b7c.cudf /home/misc2010/tmp/201108281254/packup2hy4tr-0.6/bccf69ae-db9e-11df-9a24-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.06 1.04 1.00 3/37 23446
/proc/meminfo: memFree=162404/1048576 swapFree=0/0
[pid=23445] ppid=23444 vsize=2572 CPUtime=0
/proc/23445/stat : 23445 (packup2hy4tr-0.) S 23444 23445 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 18 0 1 0 36031866 2633728 275 1283457024 134512640 135304128 4288988224 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23445/statm: 643 275 233 194 0 30 0
[pid=23446] ppid=23445 vsize=3712 CPUtime=0
/proc/23446/stat : 23446 (packup) D 23445 23445 17551 34817 17551 4202496 389 0 0 0 0 0 0 0 18 0 1 0 36031866 3801088 317 1283457024 134512640 134752139 4288379792 18446744073709551615 4294960130 0 0 18944 8192 18446744071564332000 0 0 17 0 0 0 0
/proc/23446/statm: 928 317 273 59 0 92 0

[startup+0.20427 s]
/proc/loadavg: 1.06 1.04 1.00 3/37 23446
/proc/meminfo: memFree=162404/1048576 swapFree=0/0
[pid=23445] ppid=23444 vsize=2572 CPUtime=0
/proc/23445/stat : 23445 (packup2hy4tr-0.) S 23444 23445 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 18 0 1 0 36031866 2633728 275 1283457024 134512640 135304128 4288988224 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23445/statm: 643 275 233 194 0 30 0
[pid=23446] ppid=23445 vsize=10064 CPUtime=0.16
/proc/23446/stat : 23446 (packup) R 23445 23445 17551 34817 17551 4202496 2020 0 0 0 16 0 0 0 25 0 1 0 36031866 10305536 1948 1283457024 134512640 134752139 4288379792 18446744073709551615 4159407957 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/23446/statm: 2516 1948 286 59 0 1680 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 12636

[startup+0.304257 s]
/proc/loadavg: 1.06 1.04 1.00 3/37 23446
/proc/meminfo: memFree=162404/1048576 swapFree=0/0
[pid=23445] ppid=23444 vsize=2572 CPUtime=0
/proc/23445/stat : 23445 (packup2hy4tr-0.) S 23444 23445 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 18 0 1 0 36031866 2633728 275 1283457024 134512640 135304128 4288988224 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23445/statm: 643 275 233 194 0 30 0
[pid=23446] ppid=23445 vsize=13032 CPUtime=0.25
/proc/23446/stat : 23446 (packup) R 23445 23445 17551 34817 17551 4202496 2741 0 0 0 24 1 0 0 25 0 1 0 36031866 13344768 2669 1283457024 134512640 134752139 4288379792 18446744073709551615 134681812 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/23446/statm: 3258 2669 286 59 0 2422 0
Current children cumulated CPU time (s) 0.25
Current children cumulated vsize (KiB) 15604

[startup+0.40427 s]
/proc/loadavg: 1.06 1.04 1.00 3/37 23446
/proc/meminfo: memFree=162404/1048576 swapFree=0/0
[pid=23445] ppid=23444 vsize=2572 CPUtime=0
/proc/23445/stat : 23445 (packup2hy4tr-0.) S 23444 23445 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 18 0 1 0 36031866 2633728 275 1283457024 134512640 135304128 4288988224 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23445/statm: 643 275 233 194 0 30 0
[pid=23446] ppid=23445 vsize=15804 CPUtime=0.33
/proc/23446/stat : 23446 (packup) R 23445 23445 17551 34817 17551 4202496 3432 0 0 0 32 1 0 0 25 0 1 0 36031866 16183296 3360 1283457024 134512640 134752139 4288379792 18446744073709551615 134681645 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/23446/statm: 3951 3360 286 59 0 3115 0
Current children cumulated CPU time (s) 0.33
Current children cumulated vsize (KiB) 18376

[startup+0.704295 s]
/proc/loadavg: 1.06 1.04 1.00 3/37 23446
/proc/meminfo: memFree=162404/1048576 swapFree=0/0
[pid=23445] ppid=23444 vsize=2572 CPUtime=0
/proc/23445/stat : 23445 (packup2hy4tr-0.) S 23444 23445 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 18 0 1 0 36031866 2633728 275 1283457024 134512640 135304128 4288988224 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23445/statm: 643 275 233 194 0 30 0
[pid=23446] ppid=23445 vsize=22316 CPUtime=0.53
/proc/23446/stat : 23446 (packup) R 23445 23445 17551 34817 17551 4202496 5066 0 0 0 51 2 0 0 25 0 1 0 36031866 22851584 4994 1283457024 134512640 134752139 4288379792 18446744073709551615 134613328 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/23446/statm: 5579 4994 289 59 0 4743 0
Current children cumulated CPU time (s) 0.53
Current children cumulated vsize (KiB) 24888

[startup+1.50497 s]
/proc/loadavg: 1.06 1.04 1.00 2/41 23453
/proc/meminfo: memFree=116792/1048576 swapFree=0/0
[pid=23445] ppid=23444 vsize=2572 CPUtime=0
/proc/23445/stat : 23445 (packup2hy4tr-0.) S 23444 23445 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 18 0 1 0 36031866 2633728 275 1283457024 134512640 135304128 4288988224 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23445/statm: 643 275 233 194 0 30 0
[pid=23446] ppid=23445 vsize=30604 CPUtime=0.86
/proc/23446/stat : 23446 (packup) S 23445 23445 17551 34817 17551 4202496 7170 0 0 0 72 14 0 0 25 0 1 0 36031866 31338496 7097 1283457024 134512640 134752139 4288379792 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/23446/statm: 7651 7097 324 59 0 6815 0
[pid=23448] ppid=23446 vsize=1672 CPUtime=0
/proc/23448/stat : 23448 (sh) S 23446 23445 17551 34817 17551 4202496 145 0 0 0 0 0 0 0 25 0 1 0 36031969 1712128 123 1283457024 134512640 134593992 4294900384 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/23448/statm: 418 123 108 20 0 45 0
[pid=23449] ppid=23448 vsize=2568 CPUtime=0
/proc/23449/stat : 23449 (run_h) S 23448 23445 17551 34817 17551 4202496 367 609 0 0 0 0 0 0 25 0 1 0 36031970 2629632 272 1283457024 134512640 135304128 4294439504 18446744073709551615 4294960130 0 65536 18948 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/23449/statm: 642 272 232 194 0 29 0
[pid=23453] ppid=23449 vsize=14520 CPUtime=0.46
/proc/23453/stat : 23453 (minisatp_32) R 23449 23445 17551 34817 17551 4202496 2740 0 0 0 41 5 0 0 25 0 1 0 36031970 14868480 2313 1283457024 134512640 135413687 4287990800 18446744073709551615 134752944 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/23453/statm: 3630 2313 76 220 0 3408 0
Current children cumulated CPU time (s) 1.32
Current children cumulated vsize (KiB) 51936

[startup+3.10524 s]
/proc/loadavg: 1.06 1.04 1.00 2/41 23459
/proc/meminfo: memFree=109352/1048576 swapFree=0/0
[pid=23445] ppid=23444 vsize=2572 CPUtime=0
/proc/23445/stat : 23445 (packup2hy4tr-0.) S 23444 23445 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 18 0 1 0 36031866 2633728 275 1283457024 134512640 135304128 4288988224 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23445/statm: 643 275 233 194 0 30 0
[pid=23446] ppid=23445 vsize=31840 CPUtime=2.74
/proc/23446/stat : 23446 (packup) S 23445 23445 17551 34817 17551 4202496 7788 14166 0 0 86 32 138 18 18 0 1 0 36031866 32604160 7306 1283457024 134512640 134752139 4288379792 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/23446/statm: 7960 7306 332 59 0 7124 0
Current children cumulated CPU time (s) 2.74
Current children cumulated vsize (KiB) 34412

[startup+6.30585 s]
/proc/loadavg: 1.05 1.04 1.00 3/43 23476
/proc/meminfo: memFree=101632/1048576 swapFree=0/0
[pid=23445] ppid=23444 vsize=2572 CPUtime=0
/proc/23445/stat : 23445 (packup2hy4tr-0.) S 23444 23445 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 18 0 1 0 36031866 2633728 275 1283457024 134512640 135304128 4288988224 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23445/statm: 643 275 233 194 0 30 0
[pid=23446] ppid=23445 vsize=31844 CPUtime=5.16
/proc/23446/stat : 23446 (packup) S 23445 23445 17551 34817 17551 4202496 7839 40979 0 1 93 41 340 42 18 0 1 0 36031866 32608256 7307 1283457024 134512640 134752139 4288379792 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/23446/statm: 7961 7307 332 59 0 7125 0
[pid=23466] ppid=23446 vsize=1672 CPUtime=0
/proc/23466/stat : 23466 (sh) S 23446 23445 17551 34817 17551 4202496 145 0 0 0 0 0 0 0 18 0 1 0 36032402 1712128 123 1283457024 134512640 134593992 4287966208 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/23466/statm: 418 123 108 20 0 45 0
[pid=23467] ppid=23466 vsize=2572 CPUtime=0
/proc/23467/stat : 23467 (run_h) S 23466 23445 17551 34817 17551 4202496 368 611 0 0 0 0 0 0 21 0 1 0 36032402 2633728 274 1283457024 134512640 135304128 4290418288 18446744073709551615 4294960130 0 65536 18948 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/23467/statm: 643 274 232 194 0 30 0
[pid=23471] ppid=23467 vsize=2564 CPUtime=0
/proc/23471/stat : 23471 (run_scip) S 23467 23445 17551 34817 17551 4202496 391 757 0 0 0 0 0 0 22 0 1 0 36032403 2625536 268 1283457024 134512640 135304128 4288080944 18446744073709551615 4294960130 0 65536 18948 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/23471/statm: 641 268 228 194 0 28 0
[pid=23475] ppid=23471 vsize=62560 CPUtime=0.93
/proc/23475/stat : 23475 (scip-2.0.1.linu) R 23471 23445 17551 34817 17551 4202496 14149 0 0 0 82 11 0 0 25 0 1 0 36032403 64061440 13478 1283457024 134512640 143279753 4292132816 18446744073709551615 4294960130 0 0 18944 2 0 0 0 17 0 0 0 0
/proc/23475/statm: 15640 13478 608 2141 0 13496 0
[pid=23476] ppid=23471 vsize=7196 CPUtime=0
/proc/23476/stat : 23476 (scip2v) S 23471 23445 17551 34817 17551 4202496 1008 0 0 0 0 0 0 0 18 0 1 0 36032415 7368704 847 1283457024 134512640 136477024 4288013360 18446744073709551615 4294960130 0 0 16800256 2 18446744071564457842 0 0 17 0 0 0 0
/proc/23476/statm: 1799 847 474 480 0 384 0
Current children cumulated CPU time (s) 6.09
Current children cumulated vsize (KiB) 110980

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

[startup+6.50586 s]
/proc/loadavg: 1.05 1.04 1.00 3/43 23476
/proc/meminfo: memFree=101632/1048576 swapFree=0/0
[pid=23445] ppid=23444 vsize=2572 CPUtime=0
/proc/23445/stat : 23445 (packup2hy4tr-0.) S 23444 23445 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 18 0 1 0 36031866 2633728 275 1283457024 134512640 135304128 4288988224 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23445/statm: 643 275 233 194 0 30 0
[pid=23446] ppid=23445 vsize=31844 CPUtime=5.16
/proc/23446/stat : 23446 (packup) S 23445 23445 17551 34817 17551 4202496 7839 40979 0 1 93 41 340 42 18 0 1 0 36031866 32608256 7307 1283457024 134512640 134752139 4288379792 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/23446/statm: 7961 7307 332 59 0 7125 0
[pid=23466] ppid=23446 vsize=1672 CPUtime=0
/proc/23466/stat : 23466 (sh) S 23446 23445 17551 34817 17551 4202496 145 0 0 0 0 0 0 0 18 0 1 0 36032402 1712128 123 1283457024 134512640 134593992 4287966208 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/23466/statm: 418 123 108 20 0 45 0
[pid=23467] ppid=23466 vsize=2572 CPUtime=0
/proc/23467/stat : 23467 (run_h) S 23466 23445 17551 34817 17551 4202496 368 611 0 0 0 0 0 0 21 0 1 0 36032402 2633728 274 1283457024 134512640 135304128 4290418288 18446744073709551615 4294960130 0 65536 18948 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/23467/statm: 643 274 232 194 0 30 0
[pid=23471] ppid=23467 vsize=2564 CPUtime=0
/proc/23471/stat : 23471 (run_scip) S 23467 23445 17551 34817 17551 4202496 391 757 0 0 0 0 0 0 22 0 1 0 36032403 2625536 268 1283457024 134512640 135304128 4288080944 18446744073709551615 4294960130 0 65536 18948 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/23471/statm: 641 268 228 194 0 28 0
[pid=23475] ppid=23471 vsize=62388 CPUtime=1.1
/proc/23475/stat : 23475 (scip-2.0.1.linu) R 23471 23445 17551 34817 17551 4202496 16579 0 0 0 94 16 0 0 25 0 1 0 36032403 63885312 13582 1283457024 134512640 143279753 4292132816 18446744073709551615 134757136 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/23475/statm: 15597 13582 735 2141 0 13453 0
[pid=23476] ppid=23471 vsize=7376 CPUtime=0.02
/proc/23476/stat : 23476 (scip2v) S 23471 23445 17551 34817 17551 4202496 1044 0 0 0 2 0 0 0 18 0 1 0 36032415 7553024 883 1283457024 134512640 136477024 4288013360 18446744073709551615 4294960130 0 0 16800256 2 18446744071564457842 0 0 17 0 0 0 0
/proc/23476/statm: 1844 883 479 480 0 429 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 110988

[startup+6.71399 s]
/proc/loadavg: 1.05 1.04 1.00 2/38 23476
/proc/meminfo: memFree=120560/1048576 swapFree=0/0
[pid=23445] ppid=23444 vsize=2572 CPUtime=0
/proc/23445/stat : 23445 (packup2hy4tr-0.) S 23444 23445 17551 34817 17551 4202496 380 0 0 0 0 0 0 0 18 0 1 0 36031866 2633728 275 1283457024 134512640 135304128 4288988224 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23445/statm: 643 275 233 194 0 30 0
[pid=23446] ppid=23445 vsize=31064 CPUtime=6.48
/proc/23446/stat : 23446 (packup) R 23445 23445 17551 34817 17551 4202496 14146 61000 0 1 96 44 445 63 18 0 1 0 36031866 31809536 7125 1283457024 134512640 134752139 4288379792 18446744073709551615 4157470958 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/23446/statm: 7766 7125 345 59 0 6930 0
Current children cumulated CPU time (s) 6.48
Current children cumulated vsize (KiB) 33636

Child status: 0
Real time (s): 6.74834
CPU time (s): 6.53241
CPU user time (s): 5.44834
CPU system time (s): 1.08407
CPU usage (%): 96.8002
Max. virtual memory (cumulated for all children) (KiB): 126140

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 5.44834
system time used= 1.08407
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 75869
page faults= 1
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 17899
involuntary context switches= 17991

runsolver used 0 second user time and 0.012 second system time

The end