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/27000e82-c5c4-11df-a7c5-00163e3d3b7c.cudf.dudf-real.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/dudf-real//27000e82-c5c4-11df-a7c5-00163e3d3b7c.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/27000e82-c5c4-11df-a7c5-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.35 1.15 1.05 5/34 12289
/proc/meminfo: memFree=302204/1048576 swapFree=0/0
[pid=12288] ppid=12287 vsize=2568 CPUtime=0
/proc/12288/stat : 12288 (packup2mp4pa-0.) S 12287 12288 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10573670 2629632 273 1283457024 134512640 135304128 4290612688 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/12288/statm: 642 273 233 194 0 29 0
[pid=12289] ppid=12288 vsize=4108 CPUtime=0.01
/proc/12289/stat : 12289 (packup) R 12288 12288 4778 34817 4778 4202496 533 0 0 0 1 0 0 0 25 0 1 0 10573670 4206592 462 1283457024 134512640 134752139 4291677856 18446744073709551615 134681674 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/12289/statm: 1027 462 286 59 0 191 0

[startup+0.184223 s]
/proc/loadavg: 1.35 1.15 1.05 5/34 12289
/proc/meminfo: memFree=302204/1048576 swapFree=0/0
[pid=12288] ppid=12287 vsize=2568 CPUtime=0
/proc/12288/stat : 12288 (packup2mp4pa-0.) S 12287 12288 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10573670 2629632 273 1283457024 134512640 135304128 4290612688 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/12288/statm: 642 273 233 194 0 29 0
[pid=12289] ppid=12288 vsize=9852 CPUtime=0.18
/proc/12289/stat : 12289 (packup) R 12288 12288 4778 34817 4778 4202496 1951 0 0 0 18 0 0 0 25 0 1 0 10573670 10088448 1880 1283457024 134512640 134752139 4291677856 18446744073709551615 4157091407 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/12289/statm: 2463 1880 286 59 0 1627 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 12420

[startup+0.204234 s]
/proc/loadavg: 1.35 1.15 1.05 5/34 12289
/proc/meminfo: memFree=302204/1048576 swapFree=0/0
[pid=12288] ppid=12287 vsize=2568 CPUtime=0
/proc/12288/stat : 12288 (packup2mp4pa-0.) S 12287 12288 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10573670 2629632 273 1283457024 134512640 135304128 4290612688 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/12288/statm: 642 273 233 194 0 29 0
[pid=12289] ppid=12288 vsize=10512 CPUtime=0.2
/proc/12289/stat : 12289 (packup) R 12288 12288 4778 34817 4778 4202496 2106 0 0 0 20 0 0 0 25 0 1 0 10573670 10764288 2035 1283457024 134512640 134752139 4291677856 18446744073709551615 134681583 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/12289/statm: 2628 2035 286 59 0 1792 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 13080

[startup+0.304243 s]
/proc/loadavg: 1.35 1.15 1.05 5/34 12289
/proc/meminfo: memFree=302204/1048576 swapFree=0/0
[pid=12288] ppid=12287 vsize=2568 CPUtime=0
/proc/12288/stat : 12288 (packup2mp4pa-0.) S 12287 12288 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10573670 2629632 273 1283457024 134512640 135304128 4290612688 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/12288/statm: 642 273 233 194 0 29 0
[pid=12289] ppid=12288 vsize=13288 CPUtime=0.3
/proc/12289/stat : 12289 (packup) R 12288 12288 4778 34817 4778 4202496 2807 0 0 0 29 1 0 0 25 0 1 0 10573670 13606912 2736 1283457024 134512640 134752139 4291677856 18446744073709551615 134681674 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/12289/statm: 3322 2736 286 59 0 2486 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 15856

[startup+0.704334 s]
/proc/loadavg: 1.35 1.15 1.05 5/34 12289
/proc/meminfo: memFree=302204/1048576 swapFree=0/0
[pid=12288] ppid=12287 vsize=2568 CPUtime=0
/proc/12288/stat : 12288 (packup2mp4pa-0.) S 12287 12288 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10573670 2629632 273 1283457024 134512640 135304128 4290612688 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/12288/statm: 642 273 233 194 0 29 0
[pid=12289] ppid=12288 vsize=22988 CPUtime=0.7
/proc/12289/stat : 12289 (packup) R 12288 12288 4778 34817 4778 4202496 5233 0 0 0 67 3 0 0 25 0 1 0 10573670 23539712 5162 1283457024 134512640 134752139 4291677856 18446744073709551615 134681676 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/12289/statm: 5747 5162 286 59 0 4911 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 25556

[startup+1.50447 s]
/proc/loadavg: 1.35 1.15 1.05 2/35 12290
/proc/meminfo: memFree=272608/1048576 swapFree=0/0
[pid=12288] ppid=12287 vsize=2568 CPUtime=0
/proc/12288/stat : 12288 (packup2mp4pa-0.) S 12287 12288 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10573670 2629632 273 1283457024 134512640 135304128 4290612688 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/12288/statm: 642 273 233 194 0 29 0
[pid=12289] ppid=12288 vsize=47724 CPUtime=1.5
/proc/12289/stat : 12289 (packup) R 12288 12288 4778 34817 4778 4202496 11568 0 0 0 134 16 0 0 25 0 1 0 10573670 48869376 11182 1283457024 134512640 134752139 4291677856 18446744073709551615 4158562340 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/12289/statm: 11931 11182 321 59 0 11095 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 50292

[startup+3.1048 s]
/proc/loadavg: 1.35 1.15 1.05 2/37 12292
/proc/meminfo: memFree=244800/1048576 swapFree=0/0
[pid=12288] ppid=12287 vsize=2568 CPUtime=0
/proc/12288/stat : 12288 (packup2mp4pa-0.) S 12287 12288 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10573670 2629632 273 1283457024 134512640 135304128 4290612688 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/12288/statm: 642 273 233 194 0 29 0
[pid=12289] ppid=12288 vsize=47724 CPUtime=1.66
/proc/12289/stat : 12289 (packup) S 12288 12288 4778 34817 4778 4202496 11572 0 0 0 146 20 0 0 25 0 1 0 10573670 48869376 11185 1283457024 134512640 134752139 4291677856 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/12289/statm: 11931 11185 324 59 0 11095 0
[pid=12291] ppid=12289 vsize=1672 CPUtime=0
/proc/12291/stat : 12291 (sh) S 12289 12288 4778 34817 4778 4202496 146 0 0 0 0 0 0 0 25 0 1 0 10573835 1712128 124 1283457024 134512640 134593992 4294062544 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/12291/statm: 418 124 108 20 0 45 0
[pid=12292] ppid=12291 vsize=33136 CPUtime=1.43
/proc/12292/stat : 12292 (minisatp_32) R 12291 12288 4778 34817 4778 4202496 8223 0 0 0 121 22 0 0 25 0 1 0 10573837 33931264 7255 1283457024 134512640 135413687 4289705408 18446744073709551615 134688818 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/12292/statm: 8284 7255 89 220 0 8062 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 85100

[startup+6.31215 s]
/proc/loadavg: 1.40 1.16 1.05 2/37 12294
/proc/meminfo: memFree=251496/1048576 swapFree=0/0
[pid=12288] ppid=12287 vsize=2568 CPUtime=0
/proc/12288/stat : 12288 (packup2mp4pa-0.) S 12287 12288 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10573670 2629632 273 1283457024 134512640 135304128 4290612688 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/12288/statm: 642 273 233 194 0 29 0
[pid=12289] ppid=12288 vsize=47728 CPUtime=5.13
/proc/12289/stat : 12289 (packup) S 12288 12288 4778 34817 4778 4202496 11652 27254 0 0 164 34 278 37 18 0 1 0 10573670 48873472 11194 1283457024 134512640 134752139 4291677856 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/12289/statm: 11932 11194 332 59 0 11096 0
[pid=12293] ppid=12289 vsize=1672 CPUtime=0.01
/proc/12293/stat : 12293 (sh) S 12289 12288 4778 34817 4778 4202496 147 0 0 0 0 1 0 0 18 0 1 0 10574202 1712128 124 1283457024 134512640 134593992 4286710464 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/12293/statm: 418 124 108 20 0 45 0
[pid=12294] ppid=12293 vsize=25572 CPUtime=0.97
/proc/12294/stat : 12294 (minisatp_32) R 12293 12288 4778 34817 4778 4202496 5614 0 0 0 97 0 0 0 23 0 1 0 10574203 26185728 5059 1283457024 134512640 135413687 4290344544 18446744073709551615 134971232 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/12294/statm: 6393 5059 77 220 0 6171 0
Current children cumulated CPU time (s) 6.11
Current children cumulated vsize (KiB) 77540

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

[startup+6.40219 s]
/proc/loadavg: 1.40 1.16 1.05 2/37 12294
/proc/meminfo: memFree=251496/1048576 swapFree=0/0
[pid=12288] ppid=12287 vsize=2568 CPUtime=0
/proc/12288/stat : 12288 (packup2mp4pa-0.) S 12287 12288 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10573670 2629632 273 1283457024 134512640 135304128 4290612688 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/12288/statm: 642 273 233 194 0 29 0
[pid=12289] ppid=12288 vsize=47728 CPUtime=5.13
/proc/12289/stat : 12289 (packup) S 12288 12288 4778 34817 4778 4202496 11652 27254 0 0 164 34 278 37 18 0 1 0 10573670 48873472 11194 1283457024 134512640 134752139 4291677856 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/12289/statm: 11932 11194 332 59 0 11096 0
[pid=12293] ppid=12289 vsize=1672 CPUtime=0.01
/proc/12293/stat : 12293 (sh) S 12289 12288 4778 34817 4778 4202496 147 0 0 0 0 1 0 0 18 0 1 0 10574202 1712128 124 1283457024 134512640 134593992 4286710464 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/12293/statm: 418 124 108 20 0 45 0
[pid=12294] ppid=12293 vsize=27128 CPUtime=1.06
/proc/12294/stat : 12294 (minisatp_32) R 12293 12288 4778 34817 4778 4202496 6016 0 0 0 106 0 0 0 24 0 1 0 10574203 27779072 5461 1283457024 134512640 135413687 4290344544 18446744073709551615 134536649 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/12294/statm: 6782 5461 77 220 0 6560 0
Current children cumulated CPU time (s) 6.2
Current children cumulated vsize (KiB) 79096

[startup+8.0128 s]
/proc/loadavg: 1.40 1.16 1.05 2/37 12294
/proc/meminfo: memFree=163340/1048576 swapFree=0/0
[pid=12288] ppid=12287 vsize=2568 CPUtime=0
/proc/12288/stat : 12288 (packup2mp4pa-0.) S 12287 12288 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10573670 2629632 273 1283457024 134512640 135304128 4290612688 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/12288/statm: 642 273 233 194 0 29 0
[pid=12289] ppid=12288 vsize=47728 CPUtime=5.13
/proc/12289/stat : 12289 (packup) S 12288 12288 4778 34817 4778 4202496 11652 27254 0 0 164 34 278 37 18 0 1 0 10573670 48873472 11194 1283457024 134512640 134752139 4291677856 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/12289/statm: 11932 11194 332 59 0 11096 0
[pid=12293] ppid=12289 vsize=1672 CPUtime=0.01
/proc/12293/stat : 12293 (sh) S 12289 12288 4778 34817 4778 4202496 147 0 0 0 0 1 0 0 18 0 1 0 10574202 1712128 124 1283457024 134512640 134593992 4286710464 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/12293/statm: 418 124 108 20 0 45 0
[pid=12294] ppid=12293 vsize=114388 CPUtime=2.68
/proc/12294/stat : 12294 (minisatp_32) R 12293 12288 4778 34817 4778 4202496 30919 0 0 0 240 28 0 0 25 0 1 0 10574203 117133312 25384 1283457024 134512640 135413687 4290344544 18446744073709551615 134686457 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/12294/statm: 28597 25384 107 220 0 28375 0
Current children cumulated CPU time (s) 7.82
Current children cumulated vsize (KiB) 166356

[startup+8.81312 s]
/proc/loadavg: 1.40 1.16 1.05 2/37 12294
/proc/meminfo: memFree=153792/1048576 swapFree=0/0
[pid=12288] ppid=12287 vsize=2568 CPUtime=0
/proc/12288/stat : 12288 (packup2mp4pa-0.) S 12287 12288 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10573670 2629632 273 1283457024 134512640 135304128 4290612688 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/12288/statm: 642 273 233 194 0 29 0
[pid=12289] ppid=12288 vsize=47728 CPUtime=5.13
/proc/12289/stat : 12289 (packup) S 12288 12288 4778 34817 4778 4202496 11652 27254 0 0 164 34 278 37 18 0 1 0 10573670 48873472 11194 1283457024 134512640 134752139 4291677856 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/12289/statm: 11932 11194 332 59 0 11096 0
[pid=12293] ppid=12289 vsize=1672 CPUtime=0.01
/proc/12293/stat : 12293 (sh) S 12289 12288 4778 34817 4778 4202496 147 0 0 0 0 1 0 0 18 0 1 0 10574202 1712128 124 1283457024 134512640 134593992 4286710464 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/12293/statm: 418 124 108 20 0 45 0
[pid=12294] ppid=12293 vsize=111936 CPUtime=3.47
/proc/12294/stat : 12294 (minisatp_32) R 12293 12288 4778 34817 4778 4202496 34357 0 0 0 317 30 0 0 25 0 1 0 10574203 114622464 25632 1283457024 134512640 135413687 4290344544 18446744073709551615 134686504 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/12294/statm: 27984 25632 107 220 0 27762 0
Current children cumulated CPU time (s) 8.61
Current children cumulated vsize (KiB) 163904

[startup+9.21429 s]
/proc/loadavg: 1.40 1.16 1.05 2/37 12294
/proc/meminfo: memFree=153792/1048576 swapFree=0/0
[pid=12288] ppid=12287 vsize=2568 CPUtime=0
/proc/12288/stat : 12288 (packup2mp4pa-0.) S 12287 12288 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10573670 2629632 273 1283457024 134512640 135304128 4290612688 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/12288/statm: 642 273 233 194 0 29 0
[pid=12289] ppid=12288 vsize=47728 CPUtime=5.13
/proc/12289/stat : 12289 (packup) S 12288 12288 4778 34817 4778 4202496 11652 27254 0 0 164 34 278 37 18 0 1 0 10573670 48873472 11194 1283457024 134512640 134752139 4291677856 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/12289/statm: 11932 11194 332 59 0 11096 0
[pid=12293] ppid=12289 vsize=1672 CPUtime=0.01
/proc/12293/stat : 12293 (sh) S 12289 12288 4778 34817 4778 4202496 147 0 0 0 0 1 0 0 18 0 1 0 10574202 1712128 124 1283457024 134512640 134593992 4286710464 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/12293/statm: 418 124 108 20 0 45 0
[pid=12294] ppid=12293 vsize=107920 CPUtime=3.87
/proc/12294/stat : 12294 (minisatp_32) R 12293 12288 4778 34817 4778 4202496 36208 0 0 0 357 30 0 0 25 0 1 0 10574203 110510080 25096 1283457024 134512640 135413687 4290344544 18446744073709551615 134957716 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/12294/statm: 26980 25096 107 220 0 26758 0
Current children cumulated CPU time (s) 9.01
Current children cumulated vsize (KiB) 159888

[startup+9.61444 s]
/proc/loadavg: 1.40 1.16 1.05 2/37 12294
/proc/meminfo: memFree=153792/1048576 swapFree=0/0
[pid=12288] ppid=12287 vsize=2568 CPUtime=0
/proc/12288/stat : 12288 (packup2mp4pa-0.) S 12287 12288 4778 34817 4778 4202496 376 0 0 0 0 0 0 0 18 0 1 0 10573670 2629632 273 1283457024 134512640 135304128 4290612688 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/12288/statm: 642 273 233 194 0 29 0
[pid=12289] ppid=12288 vsize=46956 CPUtime=9.41
/proc/12289/stat : 12289 (packup) R 12288 12288 4778 34817 4778 4202496 16982 63741 0 0 168 36 668 69 18 0 1 0 10573670 48082944 11013 1283457024 134512640 134752139 4291677856 18446744073709551615 4157102252 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/12289/statm: 11739 11013 344 59 0 10903 0
Current children cumulated CPU time (s) 9.41
Current children cumulated vsize (KiB) 49524

Child status: 0
Real time (s): 9.69452
CPU time (s): 9.50859
CPU user time (s): 8.42853
CPU system time (s): 1.08007
CPU usage (%): 98.0822
Max. virtual memory (cumulated for all children) (KiB): 173564

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 8.42853
system time used= 1.08007
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 85943
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= 26
involuntary context switches= 155

runsolver used 0 second user time and 0 second system time

The end