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/rand933.cudf.dudf-random.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/dudf-random//rand933.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/rand933.cudf.dudf-random.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.30 1.38 1.26 5/37 23667
/proc/meminfo: memFree=320316/1048576 swapFree=0/0
[pid=23666] ppid=23665 vsize=2568 CPUtime=0.01
/proc/23666/stat : 23666 (packup2mp4pa-0.) R 23665 23666 4778 34817 4778 4202496 359 0 0 0 1 0 0 0 25 0 1 0 11172210 2629632 273 1283457024 134512640 135304128 4292710400 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/23666/statm: 642 273 233 194 0 29 0
[pid=23667] ppid=23666 vsize=2568 CPUtime=0
/proc/23667/stat : 23667 (packup2mp4pa-0.) R 23666 23666 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 11172210 2629632 40 1283457024 134512640 135304128 4292710400 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/23667/statm: 642 40 0 194 0 29 0

[startup+0.142234 s]
/proc/loadavg: 1.30 1.38 1.26 5/37 23667
/proc/meminfo: memFree=320316/1048576 swapFree=0/0
[pid=23666] ppid=23665 vsize=2568 CPUtime=0.01
/proc/23666/stat : 23666 (packup2mp4pa-0.) S 23665 23666 4778 34817 4778 4202496 377 0 0 0 1 0 0 0 25 0 1 0 11172210 2629632 273 1283457024 134512640 135304128 4292710400 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23666/statm: 642 273 233 194 0 29 0
[pid=23667] ppid=23666 vsize=8112 CPUtime=0.12
/proc/23667/stat : 23667 (packup) R 23666 23666 4778 34817 4778 4202496 1532 0 0 0 12 0 0 0 25 0 1 0 11172210 8306688 1461 1283457024 134512640 134752139 4289039440 18446744073709551615 134694895 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/23667/statm: 2028 1461 286 59 0 1192 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 10680

[startup+0.211481 s]
/proc/loadavg: 1.30 1.38 1.26 5/37 23667
/proc/meminfo: memFree=320316/1048576 swapFree=0/0
[pid=23666] ppid=23665 vsize=2568 CPUtime=0.01
/proc/23666/stat : 23666 (packup2mp4pa-0.) S 23665 23666 4778 34817 4778 4202496 377 0 0 0 1 0 0 0 25 0 1 0 11172210 2629632 273 1283457024 134512640 135304128 4292710400 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23666/statm: 642 273 233 194 0 29 0
[pid=23667] ppid=23666 vsize=10092 CPUtime=0.18
/proc/23667/stat : 23667 (packup) R 23666 23666 4778 34817 4778 4202496 2012 0 0 0 18 0 0 0 25 0 1 0 11172210 10334208 1941 1283457024 134512640 134752139 4289039440 18446744073709551615 134682058 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/23667/statm: 2523 1941 286 59 0 1687 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 12660

[startup+0.311498 s]
/proc/loadavg: 1.30 1.38 1.26 5/37 23667
/proc/meminfo: memFree=320316/1048576 swapFree=0/0
[pid=23666] ppid=23665 vsize=2568 CPUtime=0.01
/proc/23666/stat : 23666 (packup2mp4pa-0.) S 23665 23666 4778 34817 4778 4202496 377 0 0 0 1 0 0 0 25 0 1 0 11172210 2629632 273 1283457024 134512640 135304128 4292710400 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23666/statm: 642 273 233 194 0 29 0
[pid=23667] ppid=23666 vsize=12716 CPUtime=0.28
/proc/23667/stat : 23667 (packup) R 23666 23666 4778 34817 4778 4202496 2680 0 0 0 28 0 0 0 25 0 1 0 11172210 13021184 2609 1283457024 134512640 134752139 4289039440 18446744073709551615 134681767 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/23667/statm: 3179 2609 286 59 0 2343 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 15284

[startup+0.711562 s]
/proc/loadavg: 1.30 1.38 1.26 5/37 23667
/proc/meminfo: memFree=320316/1048576 swapFree=0/0
[pid=23666] ppid=23665 vsize=2568 CPUtime=0.01
/proc/23666/stat : 23666 (packup2mp4pa-0.) S 23665 23666 4778 34817 4778 4202496 377 0 0 0 1 0 0 0 25 0 1 0 11172210 2629632 273 1283457024 134512640 135304128 4292710400 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23666/statm: 642 273 233 194 0 29 0
[pid=23667] ppid=23666 vsize=22152 CPUtime=0.68
/proc/23667/stat : 23667 (packup) R 23666 23666 4778 34817 4778 4202496 5033 0 0 0 65 3 0 0 25 0 1 0 11172210 22683648 4962 1283457024 134512640 134752139 4289039440 18446744073709551615 4157039331 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/23667/statm: 5538 4962 286 59 0 4702 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 24720

[startup+1.51173 s]
/proc/loadavg: 1.30 1.38 1.26 2/38 23668
/proc/meminfo: memFree=292900/1048576 swapFree=0/0
[pid=23666] ppid=23665 vsize=2568 CPUtime=0.01
/proc/23666/stat : 23666 (packup2mp4pa-0.) S 23665 23666 4778 34817 4778 4202496 377 0 0 0 1 0 0 0 25 0 1 0 11172210 2629632 273 1283457024 134512640 135304128 4292710400 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23666/statm: 642 273 233 194 0 29 0
[pid=23667] ppid=23666 vsize=44792 CPUtime=1.47
/proc/23667/stat : 23667 (packup) R 23666 23666 4778 34817 4778 4202496 10780 0 0 0 141 6 0 0 25 0 1 0 11172210 45867008 10660 1283457024 134512640 134752139 4289039440 18446744073709551615 134645730 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/23667/statm: 11198 10660 316 59 0 10362 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 47360

[startup+3.11283 s]
/proc/loadavg: 1.30 1.38 1.26 2/40 23670
/proc/meminfo: memFree=263744/1048576 swapFree=0/0
[pid=23666] ppid=23665 vsize=2568 CPUtime=0.01
/proc/23666/stat : 23666 (packup2mp4pa-0.) S 23665 23666 4778 34817 4778 4202496 377 0 0 0 1 0 0 0 25 0 1 0 11172210 2629632 273 1283457024 134512640 135304128 4292710400 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23666/statm: 642 273 233 194 0 29 0
[pid=23667] ppid=23666 vsize=51064 CPUtime=1.85
/proc/23667/stat : 23667 (packup) S 23666 23666 4778 34817 4778 4202496 12336 0 0 0 160 25 0 0 25 0 1 0 11172210 52289536 12013 1283457024 134512640 134752139 4289039440 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/23667/statm: 12766 12013 324 59 0 11930 0
[pid=23669] ppid=23667 vsize=1676 CPUtime=0
/proc/23669/stat : 23669 (sh) S 23667 23666 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 25 0 1 0 11172398 1716224 124 1283457024 134512640 134593992 4290807472 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/23669/statm: 419 124 108 20 0 46 0
[pid=23670] ppid=23669 vsize=29764 CPUtime=1.21
/proc/23670/stat : 23670 (minisatp_32) R 23669 23666 4778 34817 4778 4202496 7060 0 0 0 113 8 0 0 25 0 1 0 11172399 30478336 6287 1283457024 134512640 135413687 4288855280 18446744073709551615 134568419 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/23670/statm: 7441 6287 85 220 0 7219 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 85072

[startup+6.31403 s]
/proc/loadavg: 1.28 1.37 1.26 4/40 23672
/proc/meminfo: memFree=269820/1048576 swapFree=0/0
[pid=23666] ppid=23665 vsize=2568 CPUtime=0.01
/proc/23666/stat : 23666 (packup2mp4pa-0.) S 23665 23666 4778 34817 4778 4202496 377 0 0 0 1 0 0 0 25 0 1 0 11172210 2629632 273 1283457024 134512640 135304128 4292710400 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23666/statm: 642 273 233 194 0 29 0
[pid=23667] ppid=23666 vsize=51068 CPUtime=5.45
/proc/23667/stat : 23667 (packup) S 23666 23666 4778 34817 4778 4202496 12411 27500 0 0 174 41 308 22 18 0 1 0 11172210 52293632 12022 1283457024 134512640 134752139 4289039440 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/23667/statm: 12767 12022 332 59 0 11931 0
[pid=23671] ppid=23667 vsize=1672 CPUtime=0
/proc/23671/stat : 23671 (sh) S 23667 23666 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 11172759 1712128 124 1283457024 134512640 134593992 4289348944 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/23671/statm: 418 124 108 20 0 45 0
[pid=23672] ppid=23671 vsize=22588 CPUtime=0.81
/proc/23672/stat : 23672 (minisatp_32) R 23671 23666 4778 34817 4778 4202496 4822 0 0 0 80 1 0 0 22 0 1 0 11172760 23130112 4294 1283457024 134512640 135413687 4287962128 18446744073709551615 134520278 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/23672/statm: 5647 4294 77 220 0 5425 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 77896

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

[startup+6.41405 s]
/proc/loadavg: 1.28 1.37 1.26 4/40 23672
/proc/meminfo: memFree=269820/1048576 swapFree=0/0
[pid=23666] ppid=23665 vsize=2568 CPUtime=0.01
/proc/23666/stat : 23666 (packup2mp4pa-0.) S 23665 23666 4778 34817 4778 4202496 377 0 0 0 1 0 0 0 25 0 1 0 11172210 2629632 273 1283457024 134512640 135304128 4292710400 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23666/statm: 642 273 233 194 0 29 0
[pid=23667] ppid=23666 vsize=51068 CPUtime=5.45
/proc/23667/stat : 23667 (packup) S 23666 23666 4778 34817 4778 4202496 12411 27500 0 0 174 41 308 22 18 0 1 0 11172210 52293632 12022 1283457024 134512640 134752139 4289039440 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/23667/statm: 12767 12022 332 59 0 11931 0
[pid=23671] ppid=23667 vsize=1672 CPUtime=0
/proc/23671/stat : 23671 (sh) S 23667 23666 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 11172759 1712128 124 1283457024 134512640 134593992 4289348944 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/23671/statm: 418 124 108 20 0 45 0
[pid=23672] ppid=23671 vsize=24428 CPUtime=0.91
/proc/23672/stat : 23672 (minisatp_32) R 23671 23666 4778 34817 4778 4202496 5290 0 0 0 90 1 0 0 22 0 1 0 11172760 25014272 4762 1283457024 134512640 135413687 4287962128 18446744073709551615 134973595 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/23672/statm: 6107 4762 77 220 0 5885 0
Current children cumulated CPU time (s) 6.37
Current children cumulated vsize (KiB) 79736

[startup+8.01456 s]
/proc/loadavg: 1.28 1.37 1.26 2/40 23672
/proc/meminfo: memFree=189576/1048576 swapFree=0/0
[pid=23666] ppid=23665 vsize=2568 CPUtime=0.01
/proc/23666/stat : 23666 (packup2mp4pa-0.) S 23665 23666 4778 34817 4778 4202496 377 0 0 0 1 0 0 0 25 0 1 0 11172210 2629632 273 1283457024 134512640 135304128 4292710400 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23666/statm: 642 273 233 194 0 29 0
[pid=23667] ppid=23666 vsize=51068 CPUtime=5.45
/proc/23667/stat : 23667 (packup) S 23666 23666 4778 34817 4778 4202496 12411 27500 0 0 174 41 308 22 18 0 1 0 11172210 52293632 12022 1283457024 134512640 134752139 4289039440 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/23667/statm: 12767 12022 332 59 0 11931 0
[pid=23671] ppid=23667 vsize=1672 CPUtime=0
/proc/23671/stat : 23671 (sh) S 23667 23666 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 11172759 1712128 124 1283457024 134512640 134593992 4289348944 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/23671/statm: 418 124 108 20 0 45 0
[pid=23672] ppid=23671 vsize=92672 CPUtime=2.5
/proc/23672/stat : 23672 (minisatp_32) R 23671 23666 4778 34817 4778 4202496 27505 0 0 0 226 24 0 0 25 0 1 0 11172760 94896128 19948 1283457024 134512640 135413687 4287962128 18446744073709551615 134699640 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/23672/statm: 23168 19948 108 220 0 22946 0
Current children cumulated CPU time (s) 7.96
Current children cumulated vsize (KiB) 147980

[startup+8.41467 s]
/proc/loadavg: 1.28 1.37 1.26 2/40 23672
/proc/meminfo: memFree=189576/1048576 swapFree=0/0
[pid=23666] ppid=23665 vsize=2568 CPUtime=0.01
/proc/23666/stat : 23666 (packup2mp4pa-0.) S 23665 23666 4778 34817 4778 4202496 377 0 0 0 1 0 0 0 25 0 1 0 11172210 2629632 273 1283457024 134512640 135304128 4292710400 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23666/statm: 642 273 233 194 0 29 0
[pid=23667] ppid=23666 vsize=51068 CPUtime=5.45
/proc/23667/stat : 23667 (packup) S 23666 23666 4778 34817 4778 4202496 12411 27500 0 0 174 41 308 22 18 0 1 0 11172210 52293632 12022 1283457024 134512640 134752139 4289039440 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/23667/statm: 12767 12022 332 59 0 11931 0
[pid=23671] ppid=23667 vsize=1672 CPUtime=0
/proc/23671/stat : 23671 (sh) S 23667 23666 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 18 0 1 0 11172759 1712128 124 1283457024 134512640 134593992 4289348944 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/23671/statm: 418 124 108 20 0 45 0
[pid=23672] ppid=23671 vsize=98940 CPUtime=2.88
/proc/23672/stat : 23672 (minisatp_32) R 23671 23666 4778 34817 4778 4202496 28751 0 0 0 263 25 0 0 25 0 1 0 11172760 101314560 21119 1283457024 134512640 135413687 4287962128 18446744073709551615 134686212 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/23672/statm: 24735 21119 108 220 0 24513 0
Current children cumulated CPU time (s) 8.34
Current children cumulated vsize (KiB) 154248

[startup+8.81482 s]
/proc/loadavg: 1.28 1.37 1.26 2/38 23674
/proc/meminfo: memFree=272176/1048576 swapFree=0/0
[pid=23666] ppid=23665 vsize=2568 CPUtime=0.01
/proc/23666/stat : 23666 (packup2mp4pa-0.) S 23665 23666 4778 34817 4778 4202496 377 0 0 0 1 0 0 0 25 0 1 0 11172210 2629632 273 1283457024 134512640 135304128 4292710400 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23666/statm: 642 273 233 194 0 29 0
[pid=23667] ppid=23666 vsize=51072 CPUtime=8.75
/proc/23667/stat : 23667 (packup) R 23666 23666 4778 34817 4778 4202496 12492 57919 0 0 176 42 608 49 18 0 1 0 11172210 52297728 12036 1283457024 134512640 134752139 4289039440 18446744073709551615 4294960130 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/23667/statm: 12768 12036 345 59 0 11932 0
Current children cumulated CPU time (s) 8.76
Current children cumulated vsize (KiB) 53640

[startup+8.91486 s]
/proc/loadavg: 1.28 1.37 1.26 2/38 23674
/proc/meminfo: memFree=272176/1048576 swapFree=0/0
[pid=23666] ppid=23665 vsize=2568 CPUtime=0.01
/proc/23666/stat : 23666 (packup2mp4pa-0.) S 23665 23666 4778 34817 4778 4202496 377 0 0 0 1 0 0 0 25 0 1 0 11172210 2629632 273 1283457024 134512640 135304128 4292710400 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/23666/statm: 642 273 233 194 0 29 0
[pid=23667] ppid=23666 vsize=50100 CPUtime=8.84
/proc/23667/stat : 23667 (packup) R 23666 23666 4778 34817 4778 4202496 22539 57919 0 0 180 47 608 49 18 0 1 0 11172210 51302400 11793 1283457024 134512640 134752139 4289039440 18446744073709551615 4157027744 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/23667/statm: 12525 11793 345 59 0 11689 0
Current children cumulated CPU time (s) 8.85
Current children cumulated vsize (KiB) 52668

Child status: 0
Real time (s): 8.9566
CPU time (s): 8.90856
CPU user time (s): 7.9325
CPU system time (s): 0.976061
CPU usage (%): 99.4636
Max. virtual memory (cumulated for all children) (KiB): 161456

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.9325
system time used= 0.976061
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 81765
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= 182

runsolver used 0 second user time and 0 second system time

The end