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/201108251442/packup2mp4pa-0.6/e69a0e36-9ef1-11df-9d4a-00163e46d37a.cudf.dudf-real.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/dudf-real//e69a0e36-9ef1-11df-9d4a-00163e46d37a.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/e69a0e36-9ef1-11df-9d4a-00163e46d37a.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.54 1.46 1.37 4/34 30393
/proc/meminfo: memFree=288952/1048576 swapFree=0/0
[pid=30392] ppid=30391 vsize=2576 CPUtime=0
/proc/30392/stat : 30392 (packup2mp4pa-0.) S 30391 30392 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11261566 2637824 275 1283457024 134512640 135304128 4288726016 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30392/statm: 644 275 233 194 0 31 0
[pid=30393] ppid=30392 vsize=3716 CPUtime=0.01
/proc/30393/stat : 30393 (packup) R 30392 30392 4778 34817 4778 4202496 405 0 0 0 1 0 0 0 25 0 1 0 11261566 3805184 333 1283457024 134512640 134752139 4291403360 18446744073709551615 134707166 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/30393/statm: 929 333 286 59 0 93 0

[startup+0.12364 s]
/proc/loadavg: 1.54 1.46 1.37 4/34 30393
/proc/meminfo: memFree=288952/1048576 swapFree=0/0
[pid=30392] ppid=30391 vsize=2576 CPUtime=0
/proc/30392/stat : 30392 (packup2mp4pa-0.) S 30391 30392 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11261566 2637824 275 1283457024 134512640 135304128 4288726016 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30392/statm: 644 275 233 194 0 31 0
[pid=30393] ppid=30392 vsize=7952 CPUtime=0.13
/proc/30393/stat : 30393 (packup) R 30392 30392 4778 34817 4778 4202496 1485 0 0 0 13 0 0 0 25 0 1 0 11261566 8142848 1413 1283457024 134512640 134752139 4291403360 18446744073709551615 134643339 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/30393/statm: 1988 1413 286 59 0 1152 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 10528

[startup+0.213648 s]
/proc/loadavg: 1.54 1.46 1.37 4/34 30393
/proc/meminfo: memFree=288952/1048576 swapFree=0/0
[pid=30392] ppid=30391 vsize=2576 CPUtime=0
/proc/30392/stat : 30392 (packup2mp4pa-0.) S 30391 30392 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11261566 2637824 275 1283457024 134512640 135304128 4288726016 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30392/statm: 644 275 233 194 0 31 0
[pid=30393] ppid=30392 vsize=10600 CPUtime=0.22
/proc/30393/stat : 30393 (packup) R 30392 30392 4778 34817 4778 4202496 2148 0 0 0 22 0 0 0 25 0 1 0 11261566 10854400 2076 1283457024 134512640 134752139 4291403360 18446744073709551615 134681608 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/30393/statm: 2650 2076 286 59 0 1814 0
Current children cumulated CPU time (s) 0.22
Current children cumulated vsize (KiB) 13176

[startup+0.303669 s]
/proc/loadavg: 1.54 1.46 1.37 4/34 30393
/proc/meminfo: memFree=288952/1048576 swapFree=0/0
[pid=30392] ppid=30391 vsize=2576 CPUtime=0
/proc/30392/stat : 30392 (packup2mp4pa-0.) S 30391 30392 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11261566 2637824 275 1283457024 134512640 135304128 4288726016 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30392/statm: 644 275 233 194 0 31 0
[pid=30393] ppid=30392 vsize=13108 CPUtime=0.31
/proc/30393/stat : 30393 (packup) R 30392 30392 4778 34817 4778 4202496 2772 0 0 0 31 0 0 0 25 0 1 0 11261566 13422592 2700 1283457024 134512640 134752139 4291403360 18446744073709551615 134681663 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/30393/statm: 3277 2700 286 59 0 2441 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 15684

[startup+0.703733 s]
/proc/loadavg: 1.54 1.46 1.37 4/34 30393
/proc/meminfo: memFree=288952/1048576 swapFree=0/0
[pid=30392] ppid=30391 vsize=2576 CPUtime=0
/proc/30392/stat : 30392 (packup2mp4pa-0.) S 30391 30392 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11261566 2637824 275 1283457024 134512640 135304128 4288726016 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30392/statm: 644 275 233 194 0 31 0
[pid=30393] ppid=30392 vsize=23208 CPUtime=0.7
/proc/30393/stat : 30393 (packup) R 30392 30392 4778 34817 4778 4202496 5298 0 0 0 68 2 0 0 25 0 1 0 11261566 23764992 5226 1283457024 134512640 134752139 4291403360 18446744073709551615 134530392 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/30393/statm: 5802 5226 286 59 0 4966 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 25784

[startup+1.50388 s]
/proc/loadavg: 1.54 1.46 1.37 2/35 30394
/proc/meminfo: memFree=256576/1048576 swapFree=0/0
[pid=30392] ppid=30391 vsize=2576 CPUtime=0
/proc/30392/stat : 30392 (packup2mp4pa-0.) S 30391 30392 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11261566 2637824 275 1283457024 134512640 135304128 4288726016 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30392/statm: 644 275 233 194 0 31 0
[pid=30393] ppid=30392 vsize=46524 CPUtime=1.5
/proc/30393/stat : 30393 (packup) R 30392 30392 4778 34817 4778 4202496 11245 0 0 0 134 16 0 0 25 0 1 0 11261566 47640576 10858 1283457024 134512640 134752139 4291403360 18446744073709551615 4157516557 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/30393/statm: 11631 10858 321 59 0 10795 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 49100

[startup+3.10428 s]
/proc/loadavg: 1.49 1.45 1.36 2/37 30396
/proc/meminfo: memFree=230752/1048576 swapFree=0/0
[pid=30392] ppid=30391 vsize=2576 CPUtime=0
/proc/30392/stat : 30392 (packup2mp4pa-0.) S 30391 30392 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11261566 2637824 275 1283457024 134512640 135304128 4288726016 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30392/statm: 644 275 233 194 0 31 0
[pid=30393] ppid=30392 vsize=46524 CPUtime=1.58
/proc/30393/stat : 30393 (packup) S 30392 30392 4778 34817 4778 4202496 11249 0 0 0 137 21 0 0 25 0 1 0 11261566 47640576 10861 1283457024 134512640 134752139 4291403360 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/30393/statm: 11631 10861 324 59 0 10795 0
[pid=30395] ppid=30393 vsize=1676 CPUtime=0.01
/proc/30395/stat : 30395 (sh) S 30393 30392 4778 34817 4778 4202496 146 0 0 0 0 1 0 0 25 0 1 0 11261724 1716224 124 1283457024 134512640 134593992 4292413488 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/30395/statm: 419 124 108 20 0 46 0
[pid=30396] ppid=30395 vsize=35660 CPUtime=1.5
/proc/30396/stat : 30396 (minisatp_32) R 30395 30392 4778 34817 4778 4202496 8926 0 0 0 130 20 0 0 25 0 1 0 11261726 36515840 7920 1283457024 134512640 135413687 4286864128 18446744073709551615 134692025 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/30396/statm: 8915 7920 86 220 0 8693 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 86436

[startup+6.30668 s]
/proc/loadavg: 1.49 1.45 1.36 2/37 30398
/proc/meminfo: memFree=236456/1048576 swapFree=0/0
[pid=30392] ppid=30391 vsize=2576 CPUtime=0
/proc/30392/stat : 30392 (packup2mp4pa-0.) S 30391 30392 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11261566 2637824 275 1283457024 134512640 135304128 4288726016 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30392/statm: 644 275 233 194 0 31 0
[pid=30393] ppid=30392 vsize=46528 CPUtime=5.19
/proc/30393/stat : 30393 (packup) S 30392 30392 4778 34817 4778 4202496 11326 28375 0 0 157 34 297 31 18 0 1 0 11261566 47644672 10870 1283457024 134512640 134752139 4291403360 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/30393/statm: 11632 10870 332 59 0 10796 0
[pid=30397] ppid=30393 vsize=1672 CPUtime=0
/proc/30397/stat : 30397 (sh) S 30393 30392 4778 34817 4778 4202496 147 0 0 0 0 0 0 0 18 0 1 0 11262087 1712128 124 1283457024 134512640 134593992 4287320928 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/30397/statm: 418 124 108 20 0 45 0
[pid=30398] ppid=30397 vsize=28056 CPUtime=1.09
/proc/30398/stat : 30398 (minisatp_32) R 30397 30392 4778 34817 4778 4202496 6205 0 0 0 109 0 0 0 25 0 1 0 11262088 28729344 5664 1283457024 134512640 135413687 4291319616 18446744073709551615 134973170 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/30398/statm: 7014 5664 77 220 0 6792 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 78832

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

[startup+6.4067 s]
/proc/loadavg: 1.49 1.45 1.36 2/37 30398
/proc/meminfo: memFree=236456/1048576 swapFree=0/0
[pid=30392] ppid=30391 vsize=2576 CPUtime=0
/proc/30392/stat : 30392 (packup2mp4pa-0.) S 30391 30392 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11261566 2637824 275 1283457024 134512640 135304128 4288726016 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30392/statm: 644 275 233 194 0 31 0
[pid=30393] ppid=30392 vsize=46528 CPUtime=5.19
/proc/30393/stat : 30393 (packup) S 30392 30392 4778 34817 4778 4202496 11326 28375 0 0 157 34 297 31 18 0 1 0 11261566 47644672 10870 1283457024 134512640 134752139 4291403360 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/30393/statm: 11632 10870 332 59 0 10796 0
[pid=30397] ppid=30393 vsize=1672 CPUtime=0
/proc/30397/stat : 30397 (sh) S 30393 30392 4778 34817 4778 4202496 147 0 0 0 0 0 0 0 18 0 1 0 11262087 1712128 124 1283457024 134512640 134593992 4287320928 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/30397/statm: 418 124 108 20 0 45 0
[pid=30398] ppid=30397 vsize=29940 CPUtime=1.19
/proc/30398/stat : 30398 (minisatp_32) R 30397 30392 4778 34817 4778 4202496 6706 0 0 0 119 0 0 0 25 0 1 0 11262088 30658560 6165 1283457024 134512640 135413687 4291319616 18446744073709551615 134960810 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/30398/statm: 7485 6165 77 220 0 7263 0
Current children cumulated CPU time (s) 6.38
Current children cumulated vsize (KiB) 80716

[startup+8.00693 s]
/proc/loadavg: 1.45 1.44 1.36 2/37 30398
/proc/meminfo: memFree=147184/1048576 swapFree=0/0
[pid=30392] ppid=30391 vsize=2576 CPUtime=0
/proc/30392/stat : 30392 (packup2mp4pa-0.) S 30391 30392 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11261566 2637824 275 1283457024 134512640 135304128 4288726016 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30392/statm: 644 275 233 194 0 31 0
[pid=30393] ppid=30392 vsize=46528 CPUtime=5.19
/proc/30393/stat : 30393 (packup) S 30392 30392 4778 34817 4778 4202496 11326 28375 0 0 157 34 297 31 18 0 1 0 11261566 47644672 10870 1283457024 134512640 134752139 4291403360 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/30393/statm: 11632 10870 332 59 0 10796 0
[pid=30397] ppid=30393 vsize=1672 CPUtime=0
/proc/30397/stat : 30397 (sh) S 30393 30392 4778 34817 4778 4202496 147 0 0 0 0 0 0 0 18 0 1 0 11262087 1712128 124 1283457024 134512640 134593992 4287320928 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/30397/statm: 418 124 108 20 0 45 0
[pid=30398] ppid=30397 vsize=116908 CPUtime=2.79
/proc/30398/stat : 30398 (minisatp_32) R 30397 30392 4778 34817 4778 4202496 31705 0 0 0 255 24 0 0 25 0 1 0 11262088 119713792 26348 1283457024 134512640 135413687 4291319616 18446744073709551615 134689982 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/30398/statm: 29227 26348 107 220 0 29005 0
Current children cumulated CPU time (s) 7.98
Current children cumulated vsize (KiB) 167684

[startup+8.80704 s]
/proc/loadavg: 1.45 1.44 1.36 2/37 30398
/proc/meminfo: memFree=137140/1048576 swapFree=0/0
[pid=30392] ppid=30391 vsize=2576 CPUtime=0
/proc/30392/stat : 30392 (packup2mp4pa-0.) S 30391 30392 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11261566 2637824 275 1283457024 134512640 135304128 4288726016 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30392/statm: 644 275 233 194 0 31 0
[pid=30393] ppid=30392 vsize=46528 CPUtime=5.19
/proc/30393/stat : 30393 (packup) S 30392 30392 4778 34817 4778 4202496 11326 28375 0 0 157 34 297 31 18 0 1 0 11261566 47644672 10870 1283457024 134512640 134752139 4291403360 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/30393/statm: 11632 10870 332 59 0 10796 0
[pid=30397] ppid=30393 vsize=1672 CPUtime=0
/proc/30397/stat : 30397 (sh) S 30393 30392 4778 34817 4778 4202496 147 0 0 0 0 0 0 0 18 0 1 0 11262087 1712128 124 1283457024 134512640 134593992 4287320928 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/30397/statm: 418 124 108 20 0 45 0
[pid=30398] ppid=30397 vsize=114720 CPUtime=3.59
/proc/30398/stat : 30398 (minisatp_32) R 30397 30392 4778 34817 4778 4202496 35403 0 0 0 334 25 0 0 25 0 1 0 11262088 117473280 26709 1283457024 134512640 135413687 4291319616 18446744073709551615 134699071 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/30398/statm: 28680 26709 107 220 0 28458 0
Current children cumulated CPU time (s) 8.78
Current children cumulated vsize (KiB) 165496

[startup+9.60714 s]
/proc/loadavg: 1.45 1.44 1.36 2/37 30398
/proc/meminfo: memFree=137140/1048576 swapFree=0/0
[pid=30392] ppid=30391 vsize=2576 CPUtime=0
/proc/30392/stat : 30392 (packup2mp4pa-0.) S 30391 30392 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11261566 2637824 275 1283457024 134512640 135304128 4288726016 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30392/statm: 644 275 233 194 0 31 0
[pid=30393] ppid=30392 vsize=46528 CPUtime=5.19
/proc/30393/stat : 30393 (packup) S 30392 30392 4778 34817 4778 4202496 11326 28375 0 0 157 34 297 31 18 0 1 0 11261566 47644672 10870 1283457024 134512640 134752139 4291403360 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/30393/statm: 11632 10870 332 59 0 10796 0
[pid=30397] ppid=30393 vsize=1672 CPUtime=0
/proc/30397/stat : 30397 (sh) S 30393 30392 4778 34817 4778 4202496 147 0 0 0 0 0 0 0 18 0 1 0 11262087 1712128 124 1283457024 134512640 134593992 4287320928 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/30397/statm: 418 124 108 20 0 45 0
[pid=30398] ppid=30397 vsize=116512 CPUtime=4.39
/proc/30398/stat : 30398 (minisatp_32) R 30397 30392 4778 34817 4778 4202496 37633 0 0 0 413 26 0 0 25 0 1 0 11262088 119308288 26372 1283457024 134512640 135413687 4291319616 18446744073709551615 134962843 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/30398/statm: 29128 26372 107 220 0 28906 0
Current children cumulated CPU time (s) 9.58
Current children cumulated vsize (KiB) 167288

[startup+10.0091 s]
/proc/loadavg: 1.45 1.44 1.36 2/35 30398
/proc/meminfo: memFree=245780/1048576 swapFree=0/0
[pid=30392] ppid=30391 vsize=2576 CPUtime=0
/proc/30392/stat : 30392 (packup2mp4pa-0.) S 30391 30392 4778 34817 4778 4202496 380 0 0 0 0 0 0 0 18 0 1 0 11261566 2637824 275 1283457024 134512640 135304128 4288726016 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/30392/statm: 644 275 233 194 0 31 0
[pid=30393] ppid=30392 vsize=45560 CPUtime=9.99
/proc/30393/stat : 30393 (packup) R 30392 30392 4778 34817 4778 4202496 20229 66448 0 0 165 38 738 58 18 0 1 0 11261566 46653440 10640 1283457024 134512640 134752139 4291403360 18446744073709551615 134536317 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/30393/statm: 11390 10640 344 59 0 10554 0
Current children cumulated CPU time (s) 9.99
Current children cumulated vsize (KiB) 48136

Child status: 0
Real time (s): 10.0431
CPU time (s): 10.0406
CPU user time (s): 9.05657
CPU system time (s): 0.984061
CPU usage (%): 99.9753
Max. virtual memory (cumulated for all children) (KiB): 175156

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 9.05657
system time used= 0.984061
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 87985
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= 11
involuntary context switches= 165

runsolver used 0 second user time and 0 second system time

The end