Cache read error

jesper-6bce · October 17, 2024, 8:45pm

Hi,

I’m having an issue with NetDrive3. The symptom is that the application that uses the drive (Davince Resolve) freezes for roughly 60 seconds. I have enabled debug logging, and looking at the logs I can see that there seems to be an issue with the cache.

[2024/10/16 17:50:17.305] [DEBUG   ] [   20820] [FILESYSTEM] [X:Resolve.exe] FileSystem::Read => AERROR::SUCCESS : f/d/6/fd6c47dce128efc1.mov
[2024/10/16 17:50:17.305] [DEBUG   ] [   21388] [FILESYSTEM] [X:Resolve.exe] FileSystem::Read : 6, 1627660288, 28672
[2024/10/16 17:50:17.305] [DEBUG   ] [   21388] [FILESYSTEM] [X:Resolve.exe] handle found : f/d/6/fd6c47dce128efc1.mov
[2024/10/16 17:50:17.305] [DEBUG   ] [   21388] [CACHE     ] [fd6c47dce128efc1.mov] Read : 000001A768190000, 1627660288, 28672
[2024/10/16 17:50:17.305] [DEBUG   ] [   21388] [CACHE     ] [fd6c47dce128efc1.mov] [ReadonlyCache::CheckReadAhead] There is a busy read_ahead_!
[2024/10/16 17:50:17.305] [DEBUG   ] [   21388] [CACHE     ] [fd6c47dce128efc1.mov] [ReadonlyCache::QueueEmptySectors] Already 1627389952 is in sectors_.
[2024/10/16 17:50:17.305] [DEBUG   ] [   21388] [CACHE     ] [fd6c47dce128efc1.mov] [ReadonlyCache::QueueEmptySectors] Already 1627914240 is in sectors_.
[2024/10/16 17:50:17.305] [DEBUG   ] [   21388] [CACHE     ] [fd6c47dce128efc1.mov] [ReadonlyCache::QueueEmptySectors] Already 1628438528 is in sectors_.
[2024/10/16 17:50:17.403] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : 000001A768944FD0, 1538785280, 524288
[2024/10/16 17:50:17.403] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : Sector 1538785280 not reserved. Data will be overwritten on current cache 907542528
[2024/10/16 17:50:17.408] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : 000001A768944FD0, 1539309568, 524288
[2024/10/16 17:50:17.408] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : Sector 1539309568 not reserved. Data will be overwritten on current cache 908066816
[2024/10/16 17:50:17.411] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : 000001A768944FD0, 1539833856, 524288
[2024/10/16 17:50:17.411] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : Sector 1539833856 not reserved. Data will be overwritten on current cache 908591104
[2024/10/16 17:50:17.416] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : 000001A768944FD0, 1540358144, 524288
[2024/10/16 17:50:17.416] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : Sector 1540358144 not reserved. Data will be overwritten on current cache 909115392
[2024/10/16 17:50:17.421] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : 000001A768944FD0, 1540882432, 524288
[2024/10/16 17:50:17.421] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : Sector 1540882432 not reserved. Data will be overwritten on current cache 909639680
[2024/10/16 17:50:17.425] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : 000001A768944FD0, 1541406720, 524288
[2024/10/16 17:50:17.425] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : Sector 1541406720 reserved and write on 1263534080
[2024/10/16 17:50:17.430] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : 000001A768944FD0, 1541931008, 524288
[2024/10/16 17:50:17.430] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : Sector 1541931008 not reserved. Data will be overwritten on current cache 485490688
[2024/10/16 17:50:17.433] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : 000001A768944FD0, 1542455296, 524288
[2024/10/16 17:50:17.434] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : Sector 1542455296 reserved and write on 1264058368
[2024/10/16 17:50:17.438] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : 000001A768944FD0, 1542979584, 524288
[2024/10/16 17:50:17.438] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : Sector 1542979584 reserved and write on 1264582656
[2024/10/16 17:50:17.443] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : 000001A768944FD0, 1543503872, 524288
[2024/10/16 17:50:17.443] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : Sector 1543503872 not reserved. Data will be overwritten on current cache 486539264
[2024/10/16 17:50:17.447] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : 000001A768944FD0, 1544028160, 524288
[2024/10/16 17:50:17.447] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : Sector 1544028160 not reserved. Data will be overwritten on current cache 487063552
[2024/10/16 17:50:17.451] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : 000001A768944FD0, 1544552448, 524288
[2024/10/16 17:50:17.451] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : Sector 1544552448 not reserved. Data will be overwritten on current cache 487587840
[2024/10/16 17:50:17.456] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : 000001A768944FD0, 1545076736, 524288
[2024/10/16 17:50:17.456] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : Sector 1545076736 not reserved. Data will be overwritten on current cache 488112128
[2024/10/16 17:50:17.461] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : 000001A768944FD0, 1545601024, 524288
[2024/10/16 17:50:17.461] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : Sector 1545601024 reserved and write on 1265106944
[2024/10/16 17:50:17.465] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : 000001A768944FD0, 1546125312, 524288
[2024/10/16 17:50:17.465] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Fetch write : Sector 1546125312 reserved and write on 1265631232
[2024/10/16 17:50:17.465] [MESSAGE ] [   21948] [PROTOCOL  ] WEBDAV::WebDAV::Read >> HTTP GET >> 206 : http://localhost:5050/webdav/f/d/6/fd6c47dce128efc1.mov(0) - 528ms
[2024/10/16 17:50:17.465] [DEBUG   ] [   21948] [PROTOCOL  ] WEBDAV::WebDAV::Read >> ON HTTP RANGE 200(206) : AERROR::SUCCESS(0x00000000)
[2024/10/16 17:50:17.465] [MESSAGE ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Read-ahead large : clear empty reserved block(s)
[2024/10/16 17:50:17.465] [DEBUG   ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Clear reserved blocks 1513095168 to 1546649600(33554432 bytes)
[2024/10/16 17:50:17.465] [MESSAGE ] [   21948] [CACHE     ] [fd6c47dce128efc1.mov] Read-ahead large block done : 1513095168, 33554432
[2024/10/16 17:50:22.486] [DEBUG   ] [   16676] [CACHE     ] [CACHE] [C:\ProgramData\NetDrive3\_cache_\nxtedition\nxt] Total cache : 1166540800 (limits : 4294967296)
[2024/10/16 17:50:22.486] [DEBUG   ] [   16676] [CACHE     ] [fd6c47dce128efc1.mov] ClearOldCache : 41 sector(s) will clear(total 2416 sector(s))
[2024/10/16 17:50:22.494] [MESSAGE ] [   16676] [CACHE     ] [fd6c47dce128efc1.mov] ClearOldCache : OK, 1266155520 => 1244659712
[2024/10/16 17:50:36.801] [DEBUG   ] [   16676] [CACHE     ] [fd6c47dce128efc1.mov] Trying to close cache handle but there are references
[2024/10/16 17:50:42.099] [DEBUG   ] [   16676] [CACHE     ] [fd6c47dce128efc1.mov] Trying to close cache handle but there are references
[2024/10/16 17:50:47.381] [DEBUG   ] [   16676] [CACHE     ] [fd6c47dce128efc1.mov] Trying to close cache handle but there are references
[2024/10/16 17:50:52.666] [DEBUG   ] [   16676] [CACHE     ] [fd6c47dce128efc1.mov] Trying to close cache handle but there are references
[2024/10/16 17:50:52.666] [DEBUG   ] [   16676] [CACHE     ] [CACHE] [C:\ProgramData\NetDrive3\_cache_\nxtedition\nxt] Total cache : 1244659712 (limits : 4294967296)
[2024/10/16 17:50:52.666] [DEBUG   ] [   16676] [CACHE     ] [fd6c47dce128efc1.mov] ClearOldCache : 41 sector(s) will clear(total 2375 sector(s))
[2024/10/16 17:50:52.677] [MESSAGE ] [   16676] [CACHE     ] [fd6c47dce128efc1.mov] ClearOldCache : OK, 1244659712 => 1223163904
[2024/10/16 17:51:08.510] [DEBUG   ] [   16676] [CACHE     ] [fd6c47dce128efc1.mov] Trying to close cache handle but there are references
[2024/10/16 17:51:13.808] [DEBUG   ] [   16676] [CACHE     ] [fd6c47dce128efc1.mov] Trying to close cache handle but there are references
**[2024/10/16 17:51:17.310] [ERROR   ] [   21388] [CACHE     ] [fd6c47dce128efc1.mov] Read timed-out : 000001A768190000, 1627660288, 28672(last checked sector offset was 1627389952 on offset -1, length 0 and reserved)**
[2024/10/16 17:51:17.310] [DEBUG   ] [   21388] [CACHE     ] [fd6c47dce128efc1.mov] Clear reserved blocks 1627660288 to 1627688960(28672 bytes)
[2024/10/16 17:51:17.544] [MESSAGE ] [   21388] [PROTOCOL  ] WEBDAV::WebDAV::Read >> HTTP GET >> 206 : http://localhost:5050/webdav/f/d/6/fd6c47dce128efc1.mov(0) - 234ms
[2024/10/16 17:51:17.544] [DEBUG   ] [   21388] [PROTOCOL  ] WEBDAV::WebDAV::Read >> ON HTTP RANGE 200(206) : AERROR::SUCCESS(0x00000000)
[2024/10/16 17:51:17.544] [DEBUG   ] [   21388] [FILESYSTEM] [X:Resolve.exe] FileSystem::Read => AERROR::SUCCESS : f/d/6/fd6c47dce128efc1.mov
[2024/10/16 17:51:17.544] [DEBUG   ] [   20944] [FILESYSTEM] [X:Resolve.exe] FileSystem::Read : 6, 1629417472, 159744
[2024/10/16 17:51:17.545] [DEBUG   ] [   20944] [FILESYSTEM] [X:Resolve.exe] handle found : f/d/6/fd6c47dce128efc1.mov
[2024/10/16 17:51:17.545] [DEBUG   ] [   20944] [CACHE     ] [fd6c47dce128efc1.mov] Read : 000001A768190000, 1629417472, 159744
[2024/10/16 17:51:17.545] [MESSAGE ] [   20944] [CACHE     ] [fd6c47dce128efc1.mov] At ReadonlyCache::GetLargestEmptyOffset, empty_sectors_ is empty.
[2024/10/16 17:51:17.545] [DEBUG   ] [   20944] [CACHE     ] [fd6c47dce128efc1.mov] [ReadonlyCache::CheckReadAhead] Closest empty offset is within the quota!
[2024/10/16 17:51:17.545] [DEBUG   ] [   20944] [CACHE     ] [fd6c47dce128efc1.mov] Since  histsize: 10 while conf.rahit: 3ld, go read-ahead!
[2024/10/16 17:51:17.545] [MESSAGE ] [   20944] [CACHE     ] [fd6c47dce128efc1.mov] Read-ahead from 1632108544, 67108864 bytes
[2024/10/16 17:51:17.545] [DEBUG   ] [   20944] [CACHE     ] [fd6c47dce128efc1.mov] Reserved blocks 1632108544 to 1699217408(67108864 bytes)

I’ve marked the part where it’s stuck for 60 seconds in bold, and there you can see there’s an error message from the cache. Do you know why this happens? It seems to happen randomly, but especially when doing a lot of seeking in the file.

While not optimal, is there any way to disable the cache completely?

I’m using NetDrive v 3.17.960 on Windows 11. Let me know if there’s anything else you need from me to help you debug this issue so we can resolve it.

This topic looks very similar, do you know if it was resolved?

tsjeong · October 17, 2024, 11:38pm

Dear jesper-6bce,

Thank you for reaching out with the detailed logs and explanation of the issue. Unfortunately, it’s not possible to completely disable the cache in NetDrive, but there are options to reduce cache usage or modify settings to minimize the impact. Below are some relevant settings for your Drive Item configuration:

Always retrieve file list from server: This setting ensures that file lists are always fetched directly from the server without using the cache. Please note that this may reduce performance speed.
Use background uploading: When enabled, this setting stores files in the cache first, and then uploads them to the remote location. Even if the file copy appears complete in the file explorer, NetDrive may still be uploading the file in the background.
Use on-the-fly uploading in Explorer: This option disables background uploading and performs file transfers without caching. However, it may be slower than using background uploading.

Regarding the similar issue you mentioned, we haven’t received any further feedback, so we are unsure of the final outcome. However, we have since made updates to the file system in the latest version, so it’s possible that your issue could be resolved in this newer release.

Would you be open to testing it? Here is the link for the latest version (3.18.1111): Download NetDrive 3.18.1111

Please let us know how it works for you, and feel free to share additional feedback or logs if the issue persists.

Thank you

jesper-6bce · October 22, 2024, 1:26pm

We have a read-only drive, so I would be surprised if it’s related to uploads.

The always retrieve file list from server is checked.

I will test the latest version and get back to you.

jesper-6bce · October 25, 2024, 8:57am

We’re still seeing the same issue, allthough it seems to happen less often.

Would it be possible to lower the cache timeout? 60s seems really high for a local cache read, and it causes major issues with our applications hanging. Sometimes the issue happens back-to-back so there’s a 120s lockup.

tsjeong · October 27, 2024, 11:01pm

Dear Jesper,

Thank you for your patience. It seems you may be able to adjust the cache timeout settings directly to help alleviate the delays you’re experiencing.

You can find the configuration file, ndfs.ini, in the directory Program Files (x86)\Bdrive\NetDrive3\x64. Below are the key cache parameters, which you can modify according to your needs:

[CACHE]
ra_hit_streak=3                           // Cache hit streak required to initiate read-ahead
ra_min_size=1048576                       // Minimum read-ahead size in bytes
ra_max_size=268435456                     // Maximum read-ahead size in bytes
read_timeout=60000                        // Timeout for read operations from origin in milliseconds
max_fetch_from_origin=536870912           // Maximum size of a single fetch request in bytes
clear_period=30000                        // Period to check for cache clearing eligibility (ms)
clear_used_block=60                       // Expiration time for used blocks in seconds
clear_unused_block=3600                   // Expiration time for unused blocks in seconds
clear_used_block_when_quota_exceed=30     // Expiration time for used blocks if cache quota is exceeded (s)
clear_unused_block_when_quota_exceed=60   // Expiration time for unused blocks if cache quota is exceeded (s)

Of particular relevance, the read_timeout parameter (default set to 60,000 ms) can be adjusted if you find that a shorter timeout might improve your application’s responsiveness.

Please let us know if any adjustments to these parameters improve performance, or if there’s anything more we can assist you with.

Best regards.

jesper-6bce · November 3, 2024, 9:00pm

Thanks! I will give it a try.

system · November 10, 2024, 9:00pm

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.