Cool VL Viewer forum

View unanswered posts | View active topics It is currently 2022-09-26 13:01:38



Reply to topic  [ 46 posts ]  Go to page Previous  1, 2, 3, 4, 5  Next
IO Completion Port based LLLFSThread for windows & Linux 
Author Message

Joined: 2011-10-07 10:39:20
Posts: 155
Reply with quote
Good to hear.

And of course you are right about the little bugs.
Hmm, ok, messed up booleans and default initialization..., my rusty C++ skills...

Ok, yes, guess the error case should be setRequestResult(, true), the false would just requeue it which doesn't help most of the time (unless we hit some crappy virus scanners blocking the access on windows, but that usually happens on the CreateFile() call, not later).

This isn't perfect yet, as the runCondition() makes the thread spin a bit too much just waiting, which wastes a few cpu cycles. It would be better to use some of the io_uring_wait_cqe* functions to block on completions and use some form of signal (like queing a NOP sqe io_uring_prep_nop() or the equivalend https://docs.microsoft.com/en-us/window ... tionstatus ) to wake up, when some new requests get queued. Like this it is a bit of busy waiting on the completions, which improves latency, but wastes CPU.

But thats mostly optimization, as the busy wait should be quickly over in most cases.


2021-10-06 10:29:04
Profile

Joined: 2009-03-17 18:42:51
Posts: 4994
Reply with quote
Houston, we have a problem !

While it now works fine under Linux, under Windows I get failures to decode UI images at the viewer launch and finally a crash due to the llassert_always(mPendingResults > 0):
Code:
2021-10-06 17:45:44Z INFO: LLViewerTextureList::init: Preloading images (any crash would be the result of a missing image file)...
2021-10-06 17:45:45Z WARNING: LLLFSThread::threadedUpdate: IOCP GetQueuedCompletionStatus failed with code: 258
2021-10-06 17:45:45Z WARNING: LLLFSThread::Request::processRequest: Unable to do async read:997
2021-10-06 17:45:45Z WARNING: LLLFSThread::threadedUpdate: IOCP GetQueuedCompletionStatus failed with code: 258
2021-10-06 17:45:45Z WARNING: LLLFSThread::Request::processRequest: Unable to do async read:997
2021-10-06 17:45:45Z WARNING: LLLFSThread::threadedUpdate: IOCP GetQueuedCompletionStatus failed with code: 258
2021-10-06 17:45:45Z WARNING: LLLFSThread::Request::processRequest: Unable to do async read:997
2021-10-06 17:45:45Z WARNING: LLLFSThread::threadedUpdate: IOCP GetQueuedCompletionStatus failed with code: 258
2021-10-06 17:45:45Z WARNING: LLLFSThread::Request::processRequest: Unable to do async read:997
2021-10-06 17:45:45Z WARNING: LLLFSThread::threadedUpdate: IOCP GetQueuedCompletionStatus failed with code: 258
2021-10-06 17:45:45Z WARNING: LLLFSThread::Request::processRequest: Unable to do async read:997
2021-10-06 17:45:45Z WARNING: LLLFSThread::threadedUpdate: IOCP GetQueuedCompletionStatus failed with code: 258
2021-10-06 17:45:45Z WARNING: LLLFSThread::Request::processRequest: Unable to do async read:997
2021-10-06 17:45:45Z WARNING: LLLFSThread::threadedUpdate: IOCP GetQueuedCompletionStatus failed with code: 258
2021-10-06 17:45:45Z WARNING: LLLFSThread::Request::processRequest: Unable to do async read:997
2021-10-06 17:45:45Z WARNING: LLLFSThread::threadedUpdate: IOCP GetQueuedCompletionStatus failed with code: 258
2021-10-06 17:45:45Z WARNING: LLLFSThread::Request::processRequest: Unable to do async read:997
2021-10-06 17:45:45Z WARNING: LLLFSThread::threadedUpdate: IOCP GetQueuedCompletionStatus failed with code: 258
2021-10-06 17:45:45Z WARNING: LLLFSThread::Request::processRequest: Unable to do async read:997
2021-10-06 17:45:45Z WARNING: LLLFSThread::threadedUpdate: IOCP GetQueuedCompletionStatus failed with code: 258
2021-10-06 17:45:45Z WARNING: LLLFSThread::Request::processRequest: Unable to do async read:997
2021-10-06 17:45:45Z WARNING: LLLFSThread::threadedUpdate: IOCP GetQueuedCompletionStatus failed with code: 258
2021-10-06 17:45:45Z WARNING: LLLFSThread::Request::processRequest: Unable to do async read:997
2021-10-06 17:45:45Z WARNING: LLLFSThread::threadedUpdate: IOCP GetQueuedCompletionStatus failed with code: 258
2021-10-06 17:45:45Z WARNING: LLLFSThread::Request::processRequest: Unable to do async read:997
2021-10-06 17:45:45Z C:\Users\root\source\cv128244\indra\llfilesystem\lllfsthread.cpp(261) : error
2021-10-06 17:45:45Z ERROR: LLLFSThread::threadedUpdate: ASSERT (mPendingResults > 0)

On this Windows 10 installation, the viewer got its cache on a hard disk.


2021-10-06 17:52:08
Profile WWW

Joined: 2011-10-07 10:39:20
Posts: 155
Reply with quote
Will have a look.

The error codes are (from https://docs.microsoft.com/en-us/window ... --500-999-)

ERROR_IO_PENDING
997 (0x3E5)

Overlapped I/O operation is in progress.

and
WAIT_TIMEOUT

258 (0x102)

The wait operation timed out.

The WAIT_TIMEOUT is expected, when no result can be dequeued by GetQueuedCompletionStatus().
The ERROR_IO_PENDING is also no error, but expected for async i/o calls. So "unable to do async read" is kind of wrong. Might be a call that completed synchronously.


2021-10-06 20:22:22
Profile

Joined: 2009-03-17 18:42:51
Posts: 4994
Reply with quote
For the failing assert, it's likely because the ++mThread->mPendingResults; does not happen in LLLFSThread::Request::processRequest() whenever "Unable to do async" occurs... Moving the increment before the test for async would likely solve this issue (but not the failed request).


2021-10-06 20:31:33
Profile WWW

Joined: 2011-10-07 10:39:20
Posts: 155
Reply with quote
Ah, guess this is the problem:

if (!status || GetLastError() != ERROR_IO_PENDING)

status can be TRUE.

https://devblogs.microsoft.com/oldnewth ... 0/?p=12583

So, the code isn't correct for that case, that we request async-IO, but it completes already before the call returns. So it returns TRUE and we have a valid result.

It should probably be changed to read (and similar for WRITE)

Code:
          HANDLE infile =
            CreateFile(ll_convert_string_to_wide(mFileName).c_str(),
                     GENERIC_READ, FILE_SHARE_READ, NULL, OPEN_EXISTING,
                     FILE_FLAG_OVERLAPPED | FILE_FLAG_SEQUENTIAL_SCAN,
                     NULL);
         if (infile == INVALID_HANDLE_VALUE)
         {
            llwarns << "Unable to read file: " << mFileName << llendl;
            mBytesRead = 0;    // Failed
            return true;
         }
         mFile = infile;

         // Calculate offset for overlapped I/O
         if (mOffset >= 0)
         {
            mOverlapped.Offset = mOffset;
            mOverlapped.OffsetHigh = 0;
         }
         else
         {
            ULARGE_INTEGER FileSize;
            FileSize.LowPart = GetFileSize(mFile, &FileSize.HighPart);
            mOverlapped.Offset = FileSize.LowPart + mOffset;
            mOverlapped.OffsetHigh = FileSize.HighPart;
         }
         mOverlapped.hEvent = NULL;
         // Attach file handle to the IOCP
         CreateIoCompletionPort(mFile, mThread->mIOCPPort, (ULONG_PTR)this,
                           0);
         DWORD status = ReadFile(mFile, mBuffer, mBytes, NULL,
                           &mOverlapped);
         if (status == FALSE && GetLastError() != ERROR_IO_PENDING)
         {
            llwarns << "Unable to do async read: " << GetLastError()
                  << llendl;
            mBytesRead = 0;      // Failed
            return true;
         }
         ++mThread->mPendingResults;


and for WRITE
Code:
         HANDLE outfile =
            CreateFile(ll_convert_string_to_wide(mFileName).c_str(),
                     GENERIC_WRITE, FILE_SHARE_WRITE | FILE_SHARE_READ,
                     NULL, OPEN_ALWAYS, FILE_FLAG_OVERLAPPED, NULL);
         if (outfile == INVALID_HANDLE_VALUE)
         {
            llwarns << "Unable to write file: " << mFileName << llendl;
            mBytesRead = 0;    // Failed
            return true;
         }
         mFile = outfile;

         if (mOffset < 0)
         {
            // Append mode
            ULARGE_INTEGER FileSize;
            FileSize.LowPart = GetFileSize(outfile, &FileSize.HighPart);
            mOverlapped.Offset = FileSize.LowPart;
            mOverlapped.OffsetHigh = FileSize.HighPart;
         }
         else
         {
            mOverlapped.Offset = mOffset;
            mOverlapped.OffsetHigh = 0;
            mOverlapped.hEvent = NULL;
         }
         // Attach file handle to the IOCP
         CreateIoCompletionPort(mFile, mThread->mIOCPPort, (ULONG_PTR)this,
                           0);
         DWORD status = WriteFile(mFile, mBuffer, mBytes, NULL,
                            &mOverlapped);
         if (status == FALSE && GetLastError() != ERROR_IO_PENDING)
         {
            llwarns << "Unable to do async write:" << GetLastError()
                  << llendl;
            mBytesRead = 0;      // Failed
            return true;
         }
         ++mThread->mPendingResults;


2021-10-06 20:51:20
Profile

Joined: 2009-03-17 18:42:51
Posts: 4994
Reply with quote
I tried with your first suggestion:
Code:
         DWORD status = ReadFile(mFile, mBuffer, mBytes, NULL,
                           &mOverlapped);
         if (!status && GetLastError() != ERROR_IO_PENDING)
         {
            llwarns << "Unable to do async read: " << GetLastError()
                  << llendl;
            mBytesRead = 0;      // Failed
            return true;
         }
         if (status || (!status && GetLastError() == ERROR_IO_PENDING))
         {
            // Async or sync case
            ++mThread->mPendingResults;
         }
For read.
Code:
         DWORD status = WriteFile(mFile, mBuffer, mBytes, NULL,
                            &mOverlapped);
         if (!status && GetLastError() != ERROR_IO_PENDING)
         {
            llwarns << "Unable to do async write: " << GetLastError()
                  << llendl;
            mBytesRead = 0;      // Failed
            return true;
         }
         if (status || (!status && GetLastError() == ERROR_IO_PENDING))
         {
            // Async or sync case
            ++mThread->mPendingResults;
         }
For write.

With this code (tested under both Win7 and Win10), I do not crash any more, but I still get a shitload of warnings in the log (with 1000 times (!) the amount of warnings under Win10 when compared with Win7). E.g., at UI images preloading step:
Code:
2021-10-06 21:02:23Z INFO: LLViewerTextureList::init: Preloading images (any crash would be the result of a missing image file)...
2021-10-06 21:02:25Z WARNING: LLLFSThread::threadedUpdate: IOCP GetQueuedCompletionStatus failed with code: 258
2021-10-06 21:02:27Z WARNING: LLLFSThread::threadedUpdate: IOCP GetQueuedCompletionStatus failed with code: 258 (repeated 730266 times)
For Win10.
Code:
2021-10-06 21:24:52Z INFO: LLViewerTextureList::init: Preloading images (any crash would be the result of a missing image file)...
2021-10-06 21:24:52Z WARNING: LLLFSThread::threadedUpdate: IOCP GetQueuedCompletionStatus failed with code: 258
2021-10-06 21:24:52Z WARNING: LLLFSThread::threadedUpdate: IOCP GetQueuedCompletionStatus failed with code: 258 (repeated 617 times)
For Win7.


2021-10-06 21:47:29
Profile WWW

Joined: 2011-10-07 10:39:20
Posts: 155
Reply with quote
Ok, the warning is bogus. WAIT_TIMEOUT is expected and should not be logged.

It is just the slightly stupid API, the flow is the same as for io_uring_peek_cqe() with have_work = false.
Basically GetQueuedCompletionStatus() timed out waiting for the next completion, as we said 0 = no wait.
So it returns FALSE + GetLastError() == WAIT_TIMEOUT. But that case wasn't handled and spams the log.

Code:
           have_work = GetQueuedCompletionStatus(mIOCPPort, &bytes_processed,
                                   &key, &result, 0);
      LLLFSThread::Request* req = (LLLFSThread::Request*)key;
      if (have_work)
      {
         llassert_always(mPendingResults > 0);
         --mPendingResults;
         if (req)
         {
            req->setBytesRead(bytes_processed);
            setRequestResult(req, true);
         }
      }
      else if (GetLastError() == WAIT_TIMEOUT) {
         break;
      }
      else if (!result)
      {
         if (!req || GetLastError() != ERROR_ABANDONED_WAIT_0)
         {
            llwarns << "IOCP GetQueuedCompletionStatus failed with code: "
                  << GetLastError() << llendl;
         }
         else
         {
            llwarns << "IOCP for '" << req->getFilename()
                  << "' closed while waiting for completion status !"
                  << llendl;
         }
         break;
      }
      else
      {
         llassert_always(mPendingResults > 0);
         --mPendingResults;
         if (req)
         {
            llwarns << "IOCP operation for " << req->getFilename()
                  << " failed with code: " << GetLastError() << llendl;
            req->setBytesRead(0);   // An error occurred: mark as such.
            // true = resquest is over and must auto-complete
            // (self-destruct)
            setRequestResult(req, true);
            // We may have further IOCP results pending
            have_work = true;
         }
         
      }


2021-10-06 23:08:08
Profile

Joined: 2009-03-17 18:42:51
Posts: 4994
Reply with quote
Should we 'break;' in case of timeout, or let have_work loop when true ?... EDIT: have_work has already been tested to be false at that point (was obviously too sleepy when I wrote that, last night)...

What worries me is the enormous amount of timeouts we get under Win10, meaning the thread spends its time spinning for nothing with lots of GetQueuedCompletionStatus() calls.


2021-10-06 23:58:41
Profile WWW

Joined: 2011-10-07 10:39:20
Posts: 155
Reply with quote
Thats the design issue with QueuedThread i mentioned before, like this it is kind of busy wait.

The whole yield/ms_sleep() code in the run() method there is a sign it does not use proper synchronization primitives, otherwise it would just block on those.
So fixing this would involve changing run() for queued thread to actually block on some sync primitive like a mutex/wait_for_multiple_objects/io_ring_wait_cqe(), or similar instead of this busy looping/yielding.

So this is just a matter of you not seeing the "yield" calls but seeing the timeouts here. It does not get worse than before.

Now you see:

TIMEOUT
yield
TIMEOUT
yield
TIMEOUT
yield

and before it was just:

yield
yield
yield

It might be interesting to instrument the llQueuedThread run() method to see how often it just busy waits instead of doing actual work in general.


2021-10-07 10:14:44
Profile

Joined: 2009-03-17 18:42:51
Posts: 4994
Reply with quote
Well, with the fix to the bogus warning, the code now seems to work fine under Windows as well...

Its compilation will be enabled for next release, even if the setting governing its usage (UseIOUring) will still be FALSE by default (since this is still considered "experimental" code for now).

I personally could not notice any obvious difference in rezzing speed or FPS "smoothness" under either Linux (but I'm using a ram-disk for the cache with the latter, so the difference is probably very slim anyway) or Windows (tested with 7 and 10, with a cache on a hard disk), but I did not perform any serious benchmarking either... It will be interesting to get some feedback from the viewer users. :)


2021-10-07 12:09:38
Profile WWW
Display posts from previous:  Sort by  
Reply to topic   [ 46 posts ]  Go to page Previous  1, 2, 3, 4, 5  Next

Who is online

Users browsing this forum: No registered users and 1 guest


You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot post attachments in this forum

Search for:
Jump to:  
Powered by phpBB® Forum Software © phpBB Group
Designed by ST Software.