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/8b0e7c16-bab4-11e0-a883-00163e1e087d.cudf.dudf-real.log.runsolver ./packup2mp4pa-0.6 /home/misc2010/data/2011/dudf-real//8b0e7c16-bab4-11e0-a883-00163e1e087d.cudf /home/misc2010/tmp/201108251442/packup2mp4pa-0.6/8b0e7c16-bab4-11e0-a883-00163e1e087d.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.45 1.44 1.31 4/35 26332
/proc/meminfo: memFree=335368/1048576 swapFree=0/0
[pid=26331] ppid=26330 vsize=2568 CPUtime=0
/proc/26331/stat : 26331 (packup2mp4pa-0.) S 26330 26331 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11211995 2629632 274 1283457024 134512640 135304128 4286863936 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26331/statm: 642 274 233 194 0 29 0
[pid=26332] ppid=26331 vsize=3716 CPUtime=0
/proc/26332/stat : 26332 (packup) R 26331 26331 4778 34817 4778 4202496 413 0 0 0 0 0 0 0 25 0 1 0 11211995 3805184 342 1283457024 134512640 134752139 4287798000 18446744073709551615 134681805 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26332/statm: 929 342 286 59 0 93 0

[startup+0.154311 s]
/proc/loadavg: 1.45 1.44 1.31 4/35 26332
/proc/meminfo: memFree=335368/1048576 swapFree=0/0
[pid=26331] ppid=26330 vsize=2568 CPUtime=0
/proc/26331/stat : 26331 (packup2mp4pa-0.) S 26330 26331 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11211995 2629632 274 1283457024 134512640 135304128 4286863936 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26331/statm: 642 274 233 194 0 29 0
[pid=26332] ppid=26331 vsize=9300 CPUtime=0.15
/proc/26332/stat : 26332 (packup) R 26331 26331 4778 34817 4778 4202496 1829 0 0 0 15 0 0 0 25 0 1 0 11211995 9523200 1758 1283457024 134512640 134752139 4287798000 18446744073709551615 134640361 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26332/statm: 2325 1758 286 59 0 1489 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 11868

[startup+0.204318 s]
/proc/loadavg: 1.45 1.44 1.31 4/35 26332
/proc/meminfo: memFree=335368/1048576 swapFree=0/0
[pid=26331] ppid=26330 vsize=2568 CPUtime=0
/proc/26331/stat : 26331 (packup2mp4pa-0.) S 26330 26331 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11211995 2629632 274 1283457024 134512640 135304128 4286863936 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26331/statm: 642 274 233 194 0 29 0
[pid=26332] ppid=26331 vsize=11016 CPUtime=0.2
/proc/26332/stat : 26332 (packup) R 26331 26331 4778 34817 4778 4202496 2254 0 0 0 20 0 0 0 25 0 1 0 11211995 11280384 2183 1283457024 134512640 134752139 4287798000 18446744073709551615 4157701202 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26332/statm: 2754 2183 286 59 0 1918 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 13584

[startup+0.304348 s]
/proc/loadavg: 1.45 1.44 1.31 4/35 26332
/proc/meminfo: memFree=335368/1048576 swapFree=0/0
[pid=26331] ppid=26330 vsize=2568 CPUtime=0
/proc/26331/stat : 26331 (packup2mp4pa-0.) S 26330 26331 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11211995 2629632 274 1283457024 134512640 135304128 4286863936 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26331/statm: 642 274 233 194 0 29 0
[pid=26332] ppid=26331 vsize=14172 CPUtime=0.3
/proc/26332/stat : 26332 (packup) R 26331 26331 4778 34817 4778 4202496 3020 0 0 0 30 0 0 0 25 0 1 0 11211995 14512128 2949 1283457024 134512640 134752139 4287798000 18446744073709551615 134681549 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26332/statm: 3543 2949 286 59 0 2707 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16740

[startup+0.704528 s]
/proc/loadavg: 1.45 1.44 1.31 4/35 26332
/proc/meminfo: memFree=335368/1048576 swapFree=0/0
[pid=26331] ppid=26330 vsize=2568 CPUtime=0
/proc/26331/stat : 26331 (packup2mp4pa-0.) S 26330 26331 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11211995 2629632 274 1283457024 134512640 135304128 4286863936 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26331/statm: 642 274 233 194 0 29 0
[pid=26332] ppid=26331 vsize=25192 CPUtime=0.7
/proc/26332/stat : 26332 (packup) R 26331 26331 4778 34817 4778 4202496 5781 0 0 0 69 1 0 0 25 0 1 0 11211995 25796608 5710 1283457024 134512640 134752139 4287798000 18446744073709551615 134681863 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26332/statm: 6298 5710 286 59 0 5462 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 27760

[startup+1.5047 s]
/proc/loadavg: 1.45 1.44 1.31 2/36 26333
/proc/meminfo: memFree=304604/1048576 swapFree=0/0
[pid=26331] ppid=26330 vsize=2568 CPUtime=0
/proc/26331/stat : 26331 (packup2mp4pa-0.) S 26330 26331 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11211995 2629632 274 1283457024 134512640 135304128 4286863936 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26331/statm: 642 274 233 194 0 29 0
[pid=26332] ppid=26331 vsize=51036 CPUtime=1.5
/proc/26332/stat : 26332 (packup) R 26331 26331 4778 34817 4778 4202496 12325 0 0 0 141 9 0 0 25 0 1 0 11211995 52260864 12003 1283457024 134512640 134752139 4287798000 18446744073709551615 4159432062 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26332/statm: 12759 12003 321 59 0 11923 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 53604

[startup+3.10557 s]
/proc/loadavg: 1.41 1.43 1.31 2/38 26335
/proc/meminfo: memFree=274936/1048576 swapFree=0/0
[pid=26331] ppid=26330 vsize=2568 CPUtime=0
/proc/26331/stat : 26331 (packup2mp4pa-0.) S 26330 26331 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11211995 2629632 274 1283457024 134512640 135304128 4286863936 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26331/statm: 642 274 233 194 0 29 0
[pid=26332] ppid=26331 vsize=51036 CPUtime=1.68
/proc/26332/stat : 26332 (packup) S 26331 26331 4778 34817 4778 4202496 12329 0 0 0 148 20 0 0 25 0 1 0 11211995 52260864 12006 1283457024 134512640 134752139 4287798000 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26332/statm: 12759 12006 324 59 0 11923 0
[pid=26334] ppid=26332 vsize=1672 CPUtime=0
/proc/26334/stat : 26334 (sh) S 26332 26331 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 25 0 1 0 11212162 1712128 123 1283457024 134512640 134593992 4289510768 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26334/statm: 418 123 108 20 0 45 0
[pid=26335] ppid=26334 vsize=29212 CPUtime=1.41
/proc/26335/stat : 26335 (minisatp_32) R 26334 26331 4778 34817 4778 4202496 8401 0 0 0 121 20 0 0 25 0 1 0 11212164 29913088 7010 1283457024 134512640 135413687 4293093616 18446744073709551615 134686363 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26335/statm: 7303 7010 89 220 0 7081 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 84488

[startup+6.31274 s]
/proc/loadavg: 1.41 1.43 1.31 2/38 26337
/proc/meminfo: memFree=276920/1048576 swapFree=0/0
[pid=26331] ppid=26330 vsize=2568 CPUtime=0
/proc/26331/stat : 26331 (packup2mp4pa-0.) S 26330 26331 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11211995 2629632 274 1283457024 134512640 135304128 4286863936 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26331/statm: 642 274 233 194 0 29 0
[pid=26332] ppid=26331 vsize=51040 CPUtime=5.02
/proc/26332/stat : 26332 (packup) S 26331 26331 4778 34817 4778 4202496 12402 26943 0 0 162 36 276 28 18 0 1 0 11211995 52264960 12015 1283457024 134512640 134752139 4287798000 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26332/statm: 12760 12015 332 59 0 11924 0
[pid=26336] ppid=26332 vsize=1672 CPUtime=0
/proc/26336/stat : 26336 (sh) S 26332 26331 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 11212507 1712128 123 1283457024 134512640 134593992 4287306576 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26336/statm: 418 123 108 20 0 45 0
[pid=26337] ppid=26336 vsize=28732 CPUtime=1.18
/proc/26337/stat : 26337 (minisatp_32) R 26336 26331 4778 34817 4778 4202496 6782 0 0 0 111 7 0 0 24 0 1 0 11212508 29421568 5962 1283457024 134512640 135413687 4293734800 18446744073709551615 134714635 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26337/statm: 7183 5962 85 220 0 6961 0
Current children cumulated CPU time (s) 6.2
Current children cumulated vsize (KiB) 84012

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

[startup+6.41277 s]
/proc/loadavg: 1.41 1.43 1.31 2/38 26337
/proc/meminfo: memFree=276920/1048576 swapFree=0/0
[pid=26331] ppid=26330 vsize=2568 CPUtime=0
/proc/26331/stat : 26331 (packup2mp4pa-0.) S 26330 26331 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11211995 2629632 274 1283457024 134512640 135304128 4286863936 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26331/statm: 642 274 233 194 0 29 0
[pid=26332] ppid=26331 vsize=51040 CPUtime=5.02
/proc/26332/stat : 26332 (packup) S 26331 26331 4778 34817 4778 4202496 12402 26943 0 0 162 36 276 28 18 0 1 0 11211995 52264960 12015 1283457024 134512640 134752139 4287798000 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26332/statm: 12760 12015 332 59 0 11924 0
[pid=26336] ppid=26332 vsize=1672 CPUtime=0
/proc/26336/stat : 26336 (sh) S 26332 26331 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 11212507 1712128 123 1283457024 134512640 134593992 4287306576 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26336/statm: 418 123 108 20 0 45 0
[pid=26337] ppid=26336 vsize=30072 CPUtime=1.28
/proc/26337/stat : 26337 (minisatp_32) R 26336 26331 4778 34817 4778 4202496 7327 0 0 0 119 9 0 0 24 0 1 0 11212508 30793728 6391 1283457024 134512640 135413687 4293734800 18446744073709551615 134988446 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26337/statm: 7518 6391 85 220 0 7296 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 85352

[startup+7.21298 s]
/proc/loadavg: 1.41 1.43 1.31 2/38 26337
/proc/meminfo: memFree=253368/1048576 swapFree=0/0
[pid=26331] ppid=26330 vsize=2568 CPUtime=0
/proc/26331/stat : 26331 (packup2mp4pa-0.) S 26330 26331 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11211995 2629632 274 1283457024 134512640 135304128 4286863936 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26331/statm: 642 274 233 194 0 29 0
[pid=26332] ppid=26331 vsize=51040 CPUtime=5.02
/proc/26332/stat : 26332 (packup) S 26331 26331 4778 34817 4778 4202496 12402 26943 0 0 162 36 276 28 18 0 1 0 11211995 52264960 12015 1283457024 134512640 134752139 4287798000 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26332/statm: 12760 12015 332 59 0 11924 0
[pid=26336] ppid=26332 vsize=1672 CPUtime=0
/proc/26336/stat : 26336 (sh) S 26332 26331 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 11212507 1712128 123 1283457024 134512640 134593992 4287306576 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26336/statm: 418 123 108 20 0 45 0
[pid=26337] ppid=26336 vsize=89680 CPUtime=2.08
/proc/26337/stat : 26337 (minisatp_32) R 26336 26331 4778 34817 4778 4202496 23979 0 0 0 181 27 0 0 25 0 1 0 11212508 91832320 19008 1283457024 134512640 135413687 4293734800 18446744073709551615 134656722 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26337/statm: 22420 19008 108 220 0 22198 0
Current children cumulated CPU time (s) 7.1
Current children cumulated vsize (KiB) 144960

[startup+8.01321 s]
/proc/loadavg: 1.38 1.42 1.31 2/38 26337
/proc/meminfo: memFree=205132/1048576 swapFree=0/0
[pid=26331] ppid=26330 vsize=2568 CPUtime=0
/proc/26331/stat : 26331 (packup2mp4pa-0.) S 26330 26331 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11211995 2629632 274 1283457024 134512640 135304128 4286863936 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26331/statm: 642 274 233 194 0 29 0
[pid=26332] ppid=26331 vsize=51040 CPUtime=5.02
/proc/26332/stat : 26332 (packup) S 26331 26331 4778 34817 4778 4202496 12402 26943 0 0 162 36 276 28 18 0 1 0 11211995 52264960 12015 1283457024 134512640 134752139 4287798000 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26332/statm: 12760 12015 332 59 0 11924 0
[pid=26336] ppid=26332 vsize=1672 CPUtime=0
/proc/26336/stat : 26336 (sh) S 26332 26331 4778 34817 4778 4202496 145 0 0 0 0 0 0 0 18 0 1 0 11212507 1712128 123 1283457024 134512640 134593992 4287306576 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26336/statm: 418 123 108 20 0 45 0
[pid=26337] ppid=26336 vsize=98692 CPUtime=2.88
/proc/26337/stat : 26337 (minisatp_32) R 26336 26331 4778 34817 4778 4202496 28440 0 0 0 260 28 0 0 25 0 1 0 11212508 101060608 20936 1283457024 134512640 135413687 4293734800 18446744073709551615 134698551 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26337/statm: 24673 20936 108 220 0 24451 0
Current children cumulated CPU time (s) 7.9
Current children cumulated vsize (KiB) 153972

[startup+8.40511 s]
/proc/loadavg: 1.38 1.42 1.31 2/38 26337
/proc/meminfo: memFree=205132/1048576 swapFree=0/0
[pid=26331] ppid=26330 vsize=2568 CPUtime=0
/proc/26331/stat : 26331 (packup2mp4pa-0.) S 26330 26331 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11211995 2629632 274 1283457024 134512640 135304128 4286863936 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26331/statm: 642 274 233 194 0 29 0
[pid=26332] ppid=26331 vsize=51044 CPUtime=8.29
/proc/26332/stat : 26332 (packup) R 26331 26331 4778 34817 4778 4202496 14621 57027 0 0 162 40 568 59 18 0 1 0 11211995 52269056 12029 1283457024 134512640 134752139 4287798000 18446744073709551615 134525484 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26332/statm: 12761 12029 345 59 0 11925 0
Current children cumulated CPU time (s) 8.29
Current children cumulated vsize (KiB) 53612

[startup+8.50701 s]
/proc/loadavg: 1.38 1.42 1.31 2/38 26337
/proc/meminfo: memFree=205132/1048576 swapFree=0/0
[pid=26331] ppid=26330 vsize=2568 CPUtime=0
/proc/26331/stat : 26331 (packup2mp4pa-0.) S 26330 26331 4778 34817 4778 4202496 377 0 0 0 0 0 0 0 18 0 1 0 11211995 2629632 274 1283457024 134512640 135304128 4286863936 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26331/statm: 642 274 233 194 0 29 0
[pid=26332] ppid=26331 vsize=0 CPUtime=8.4
/proc/26332/stat : 26332 (packup) R 26331 26331 4778 34817 4778 4202500 23451 57027 0 0 169 44 568 59 18 0 1 0 11211995 0 0 1283457024 0 0 0 0 0 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26332/statm: 0 0 0 0 0 0 0
Current children cumulated CPU time (s) 8.4
Current children cumulated vsize (KiB) 2568

Child status: 0
Real time (s): 8.51219
CPU time (s): 8.42053
CPU user time (s): 7.38046
CPU system time (s): 1.04006
CPU usage (%): 98.9232
Max. virtual memory (cumulated for all children) (KiB): 161048

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.38046
system time used= 1.04007
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 80865
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= 13
involuntary context switches= 140

runsolver used 0 second user time and 0 second system time

The end