<div dir="ltr"><div dir="ltr">I added the tracerfs command to the shell. Not sure why that's not already there. I enabled all with "tracerfs set all". It took a while, but I did run into the problem. The end of the log is below. Can you see what the kernel is trying to do and what its waiting on from this? It's going to be a while, reading through kernel code, to understand exactly what this means.<div><br></div><div><div>rtems-rfs: buffer-scan: count=58, block=1: 2252 2237 2223 2205 2188 2169 2153 2132 2119 2098 2079 2068 2049 2031 2015 2001 1984 1965 1955 1934 1915 1894 1873 1853 1838 1817 1796 1775 1761 1741 1724 1717 1696 1675 1658 1641 1622 1601 1581 1563 1544 1524 1508 1494 1476 1467 1448 1427 1406 1326 1292 1246 1236 1218 1199 1181 1162 1053 : not found</div><div>rtems-rfs: buffer-scan: count=4, block=1: 2267 1 : found block=1</div><div>rtems-rfs: buffer-request: block=1 bdbuf-read=1 refs=1</div><div>rtems-rfs: buffer-release: block=1 (dirty) refs=1 </div><div>rtems-rfs: group-bitmap-alloc: block allocated: 2268</div><div>rtems-rfs: buffer-request: block=2268</div><div>rtems-rfs: buffer-scan: count=58, block=2268: 2252 2237 2223 2205 2188 2169 2153 2132 2119 2098 2079 2068 2049 2031 2015 2001 1984 1965 1955 1934 1915 1894 1873 1853 1838 1817 1796 1775 1761 1741 1724 1717 1696 1675 1658 1641 1622 1601 1581 1563 1544 1524 1508 1494 1476 1467 1448 1427 1406 1326 1292 1246 1236 1218 1199 1181 1162 1053 : not found</div><div>rtems-rfs: buffer-scan: count=4, block=2268: 1 2267 2266 2265 : not found</div><div>rtems-rfs: buffer-request: block=2268 bdbuf-get=2268 refs=1</div><div>rtems-rfs: buffer-release: block=2268 (dirty) refs=1 </div><div>rtems-rfs: block-map-grow: entry: blocks=1 count=4</div><div>rtems-rfs: buffer-request: block=1</div><div>rtems-rfs: buffer-scan: count=58, block=1: 2252 2237 2223 2205 2188 2169 2153 2132 2119 2098 2079 2068 2049 2031 2015 2001 1984 1965 1955 1934 1915 1894 1873 1853 1838 1817 1796 1775 1761 1741 1724 1717 1696 1675 1658 1641 1622 1601 1581 1563 1544 1524 1508 1494 1476 1467 1448 1427 1406 1326 1292 1246 1236 1218 1199 1181 1162 1053 : not found</div><div>rtems-rfs: buffer-scan: count=5, block=1: 2268 1 : found block=1</div><div>rtems-rfs: buffer-request: block=1 bdbuf-read=1 refs=1</div><div>rtems-rfs: buffer-release: block=1 (dirty) refs=1 </div><div>rtems-rfs: group-bitmap-alloc: block allocated: 2269</div><div>rtems-rfs: buffer-request: block=2269</div><div>rtems-rfs: buffer-scan: count=58, block=2269: 2252 2237 2223 2205 2188 2169 2153 2132 2119 2098 2079 2068 2049 2031 2015 2001 1984 1965 1955 1934 1915 1894 1873 1853 1838 1817 1796 1775 1761 1741 1724 1717 1696 1675 1658 1641 1622 1601 1581 1563 1544 1524 1508 1494 1476 1467 1448 1427 1406 1326 1292 1246 1236 1218 1199 1181 1162 1053 : not found</div><div>rtems-rfs: buffer-scan: count=5, block=2269: 1 2268 2267 2266 2265 : not found</div><div>rtems-rfs: buffer-request: block=2269 bdbuf-get=2269 refs=1</div><div>rtems-rfs: buffer-release: block=2269 (dirty) refs=1 </div><div>rtems-rfs: buffer-release: local cache overflow: 5</div><div>rtems-rfs: bdbuf-release: block=0 bdbuf=2265 (modified)</div><div>rtems-rfs: block-map-grow: entry: blocks=1 count=5</div><div>rtems-rfs: buffer-request: block=1</div><div>rtems-rfs: buffer-scan: count=58, block=1: 2252 2237 2223 2205 2188 2169 2153 2132 2119 2098 2079 2068 2049 2031 2015 2001 1984 1965 1955 1934 1915 1894 1873 1853 1838 1817 1796 1775 1761 1741 1724 1717 1696 1675 1658 1641 1622 1601 1581 1563 1544 1524 1508 1494 1476 1467 1448 1427 1406 1326 1292 1246 1236 1218 1199 1181 1162 1053 : not found</div><div>rtems-rfs: buffer-scan: count=5, block=1: 2269 1 : found block=1</div><div>rtems-rfs: buffer-request: block=1 bdbuf-read=1 refs=1</div><div>rtems-rfs: buffer-release: block=1 (dirty) refs=1 </div><div>rtems-rfs: group-bitmap-alloc: block allocated: 2270</div><div>rtems-rfs: buffer-request: block=1</div><div>rtems-rfs: buffer-scan: count=58, block=1: 2252 2237 2223 2205 2188 2169 2153 2132 2119 2098 2079 2068 2049 2031 2015 2001 1984 1965 1955 1934 1915 1894 1873 1853 1838 1817 1796 1775 1761 1741 1724 1717 1696 1675 1658 1641 1622 1601 1581 1563 1544 1524 1508 1494 1476 1467 1448 1427 1406 1326 1292 1246 1236 1218 1199 1181 1162 1053 : not found</div><div>rtems-rfs: buffer-scan: count=5, block=1: 1 : found block=1</div><div>rtems-rfs: buffer-request: block=1 bdbuf-read=1 refs=1</div><div>rtems-rfs: buffer-release: block=1 (dirty) refs=1 </div><div>rtems-rfs: group-bitmap-alloc: block allocated: 2271</div><div>rtems-rfs: buffer-request: block=2271</div><div>rtems-rfs: buffer-scan: count=58, block=2271: 2252 2237 2223 2205 2188 2169 2153 2132 2119 2098 2079 2068 2049 2031 2015 2001 1984 1965 1955 1934 1915 1894 1873 1853 1838 1817 1796 1775 1761 1741 1724 1717 1696 1675 1658 1641 1622 1601 1581 1563 1544 1524 1508 1494 1476 1467 1448 1427 1406 1326 1292 1246 1236 1218 1199 1181 1162 1053 : not found</div><div>rtems-rfs: buffer-scan: count=5, block=2271: 1 2269 2268 2267 2266 : not found</div><div>rtems-rfs: buffer-request: block=2271 bdbuf-get=2271 refs=1</div><div>rtems-rfs: block-map-grow: upping: block-count=5</div><div>rtems-rfs: buffer-request: block=2270</div><div>rtems-rfs: buffer-scan: count=59, block=2270: 2271 2252 2237 2223 2205 2188 2169 2153 2132 2119 2098 2079 2068 2049 2031 2015 2001 1984 1965 1955 1934 1915 1894 1873 1853 1838 1817 1796 1775 1761 1741 1724 1717 1696 1675 1658 1641 1622 1601 1581 1563 1544 1524 1508 1494 1476 1467 1448 1427 1406 1326 1292 1246 1236 1218 1199 1181 1162 1053 : not found</div><div>rtems-rfs: buffer-scan: count=5, block=2270: 1 2269 2268 2267 2266 : not found</div></div><div><br></div><div><br></div><div>All trace events immediately stop here.</div></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Tue, Oct 8, 2019 at 9:30 AM Mathew Benson <<a href="mailto:mbenson@windhoverlabs.com">mbenson@windhoverlabs.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div>I don't have a test case that I can post or give away, yet. I may put one together later.</div><div><br></div><div>Yes. All 4 tasks are on that same conditional wait. The condition is a response from a block device. The test case is hammering the RAM disk. I wrote some of the flash drivers but as far as I know, the RAM disk was used as is so I haven't looked at the code. That conditional wait does not have a time out so it just pends forever.<br></div><div><br></div><div>Thanks. I'll try the RFS trace when I have time. Unfortunately, this is late in the development cycle so I don't have ready access to the article under test. Loading it with non production code takes time. Trying to reproduce it on a non production environment. For now, all I have is shell commands and manually decoding dumped memory.</div><div><br></div><div>Somebody more knowledgable on the inner workings of the RTEMS kernel expressed concern a while ago that heavy use of the RAM disk could basically out run the kernel worker thread. I noted it but didn't ask about the mechanics of how or why that could happen. Are requests to the worker threads in a lossy queue? Is it possible the request is getting dropped? <br></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Mon, Oct 7, 2019 at 11:30 PM Chris Johns <<a href="mailto:chrisj@rtems.org" target="_blank">chrisj@rtems.org</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">On 8/10/19 12:53 pm, Mathew Benson wrote:<br>
> I'm using RTEMS 5 on a LEON3. I'm troubleshooting a failure condition that<br>
> occurs when stress test reading and writing to and from RAM disk. RAM disk to<br>
> RAM disk. When the condition is tripped, it appears that I have 4 tasks that<br>
> are pending on conditions that just never happens. <br>
<br>
Do you have a test case?<br>
<br>
> The task command shows:<br>
> <br>
> ID NAME SHED PRI STATE MODES EVENTS WAITINFO<br>
> ------------------------------------------------------------------------------<br>
> 0a01000c TSKA UPD 135 MTX P:T:nA NONE RFS<br>
> 0a01001f TSKB UPD 135 CV P:T:nA NONE bdbuf access<br>
> 0a010020 TSKC UPD 150 MTX P:T:nA NONE RFS<br>
> 0a010032 TSKD UPD 245 MTX P:T:nA NONE RFS<br>
<br>
It looks like TSKA, TSKC and TSKD are waiting for the RFS lock and TSKB is<br>
blocked in a bdbuf access. I wonder why that is blocked?<br>
<br>
The RFS hold's it lock over the bdbuf calls.<br>
> <br>
> None of my tasks appear to be failed. Nobody is pending on anything noticeable<br>
> except the 4 above. The conditional wait is a single shared resource so any<br>
> attempt to access the file system after this happens results in yet another<br>
> forever pended task.<br>
> <br>
> Digging into source code, it appears that the kernel is waiting for a specific<br>
> response from a block device, but just didn't get what its expecting. The next<br>
> thing is to determine which block device the kernel is pending on, what the<br>
> expected response is, and what the block device actually did. Can anybody shed<br>
> some light on this or recommend some debugging steps? I'm trying to exhaust<br>
> all I can do before I start manually decoding machine code.<br>
<br>
The RFS has trace support you can access via `rtems/rfs/rtems-rfs-trace.h`. You<br>
can set the trace mask in your code or you can can call<br>
`rtems_rfs_trace_shell_command()` with suitable arguments or hook it to an<br>
existing shell. There is a buffer trace flag that show the release calls to bdbuf ..<br>
<br>
RTEMS_RFS_TRACE_BUFFER_RELEASE<br>
<br>
There is no trace call to get or read. Maybe add a get/read trace as well.<br>
<br>
The RAM disk also has trace in the code which can be enabled by editing the file.<br>
<br>
Chris<br>
</blockquote></div><br clear="all"><br>-- <br><div dir="ltr"><div dir="ltr"><div><div dir="ltr"><div><div><div><b>Mathew Benson</b><br></div>CEO | Chief Engineer<br></div>Windhover Labs, LLC<br>832-640-4018<br><br><img src="https://drive.google.com/a/windhoverlabs.com/uc?id=1cLDczWESrU667xKgEJlFhHa2yjq5UVhJ&export=download"><br></div><a href="http://www.windhoverlabs.com" target="_blank">www.windhoverlabs.com</a><br><br></div></div></div></div>
</blockquote></div><br clear="all"><div><br></div>-- <br><div dir="ltr" class="gmail_signature"><div dir="ltr"><div><div dir="ltr"><div><div><div><b>Mathew Benson</b><br></div>CEO | Chief Engineer<br></div>Windhover Labs, LLC<br>832-640-4018<br><br><img src="https://drive.google.com/a/windhoverlabs.com/uc?id=1cLDczWESrU667xKgEJlFhHa2yjq5UVhJ&export=download"><br></div><a href="http://www.windhoverlabs.com" target="_blank">www.windhoverlabs.com</a><br><br></div></div></div></div>