IOS: Emulate FS timings for ES content IPC commands #9511

leoetlino · 2021-02-14T01:13:19Z

Filesystem accesses aren't magically faster when they are done by ES,
so this commit changes our content wrapper IPC commands to take FS
access times and read operations into account.

This should make content read timings a lot more accurate and closer
to console. Note that the accuracy of the timings are limited to the
accuracy of the emulated FS timings, and currently performance
differences between IOS9-IOS28 and newer IOS versions are not emulated.

Part 1 of fixing https://bugs.dolphin-emu.org/issues/11346
(part 2 will involve emulating those differences)

iwubcode · 2021-02-14T02:11:46Z

@leoetlino - anything in particular to test or anything to watch out for when testing?

JMC47 · 2021-02-14T03:43:21Z

The Wii System Menu is crashing when I try to access my Channel List in the Data Management screen. This does not happen in master.

Nevermind, it can happen on Master too, it depends on me accessing menus in a certain order.

leoetlino · 2021-02-14T12:06:13Z

@iwubcode just making sure the system menu and NAND (including WiiWare) titles still work, nothing too specific

JMC said most games don't care about the timing changes, it's just VC games that take longer to load now.

BhaaLseN

Code seems good, nothing that sticks out - but untested.

JMC47 · 2021-02-14T13:16:44Z

We solved the crash. Netplay corrupted my NAND at some point.

leoetlino · 2021-02-14T13:17:40Z

yep, turned out there was a missing TMD for Dokapon Kingdom. It's why we enforce the requirement that games must be launched at least once before its save can be imported, but I guess this doesn't happen with netplay.

Source/Core/Core/IOS/ES/TitleContents.cpp

leoetlino · 2021-02-15T01:10:17Z

After thinking about this a bit more, I'm not entirely satisfied with the way ticks are kept track of in the ES code -- I think that ideally ES shouldn't have to increment the number of ticks manually after each call to FS. I'll try to find a way to make that cleaner...

leoetlino · 2021-02-16T01:15:01Z

Still WIP, but I changed the way ticks were accumulated. For the new version of the third and fourth commits, I recommend reviewing with "Hide whitespace changes" enabled to make the diff less noisy.

I plan to address @Pokechu22's comment tomorrow.

Source/Core/Core/IOS/ES/TitleContents.cpp

iwubcode · 2021-02-17T05:11:42Z

Source/Core/Core/IOS/IOS.h

+class Ticks
+{
+public:
+  Ticks(u64* ticks = nullptr) : m_ticks(ticks) {}


explicit ?

In this case, we actually want implicit conversions to Ticks as this class is for all intents and purposes just a wrapper around a u64* and having to write Ticks{...} every time would be very verbose.

iwubcode · 2021-02-17T05:24:55Z

Source/Core/Core/IOS/FS/FileSystemProxy.cpp

-  auto backend_fd = m_ios.GetFS()->OpenFile(request.uid, request.gid, request.path,
-                                            static_cast<Mode>(request.flags & 3));
-  LogResult(backend_fd, "OpenFile({})", request.path);
+  auto backend_fd = m_ios.GetFS()->OpenFile(uid, gid, path, mode);


ticks doesn't seem to be used. Did you mean to pass it into OpenFile here?

Actually, I see this quite a bit. What is the point of updating the ticks when they are passed in as a copy?

The number of ticks is estimated and ticks is updated two lines above -- the underlying backend doesn't know anything about timings.

ticks isn't an integer, it's a small wrapper around a u64*, which is why it is passed by value.

Thanks @leoetlino for your explanation. I believe in my second comment I was confused ^^. In my first comment, I was aware of the u64* but thought the ticks were used in an underlying call somewhere.

Re-reading, I missed an important part. The ticks are ultimately passed in to the IPCReply structure via the MakeIPCReply function which I think helps determine the delay call for the command? Either the delay time is built up from 0 or it is built up from IPCOverheadTicks depending on the call.

Sorry for all the dumb comments!

Yes, that's correct. MakeIPCReply is used to help construct an IPCReply with timing information and without having to duplicate the IPCReply{..., ticks} for every return.

Source/Core/Core/IOS/ES/TitleContents.cpp

sepalani · 2021-02-18T03:32:27Z

Source/Core/Core/IOS/ES/Formats.cpp

 {
  u64 title_id = 0;
-  if (!file.Read(&title_id, 1))
+  if (fs.Read(fd, &title_id, 1, ticks) != sizeof(title_id))


Can't a constant be used to indicate an invalid read or an invalid title_id rather than relying on sizeof?

sizeof(title_id) is that constant. I could hardcode 8 but I think that's worse than using sizeof.

I see, I just find odd that the Read function can have an error state and it's not being used to handle the error. I understand the reasoning behind this use of sizeof in the case of partially read. Maybe that's just me but I find it strange to read.

If there is an error, Read() returns a negative value so the comparison will be false in that case. Or am I misunderstanding your comment?

I was just saying that having if (Read(..., &var, ...) != READ_SIZE) rather than if (Read(..., &var, ...) < 0)/if (Read(..., &var, ...) == ERROR seems a bit odd to read to me.

Feel free to disregard that comment.

Oh, I see what you mean. But if we do if (Read(..., &var, ...) < 0) we still also need to check for partial reads, so we'd have to do something like

const int ret = Read(...); if (ret < 0 || ret != READ_SIZE) ...

which seems redundant to me, since READ_SIZE is positive.

sepalani · 2021-02-18T03:33:10Z

Source/Core/Core/IOS/ES/Formats.cpp

    return {};

  u32 uid = 0;
-  if (!file.Read(&uid, 1))
+  if (fs.Read(fd, &uid, 1, ticks) != sizeof(uid))


Ditto for sizeof and uid.

Source/Core/Core/IOS/ES/Formats.cpp

Source/Core/Core/IOS/ES/NandUtils.cpp

Source/Core/Core/IOS/ES/ES.h

The content ID/index is what actually matters..

We log FS reads already, might as well log ES content reads.

This makes it more convenient to emulate timings for IPC commands that perform internal IOS <-> IOS IPC, for example ES relying on FS for filesystem access.

Filesystem accesses aren't magically faster when they are done by ES, so this commit changes our content wrapper IPC commands to take FS access times and read operations into account. This should make content read timings a lot more accurate and closer to console. Note that the accuracy of the timings are limited to the accuracy of the emulated FS timings, and currently performance differences between IOS9-IOS28 and newer IOS versions are not emulated. Part 1 of fixing https://bugs.dolphin-emu.org/issues/11346 (part 2 will involve emulating those differences)

Source/Core/Core/IOS/FS/FileSystemProxy.cpp

leoetlino added the needs testing label Feb 14, 2021

leoetlino added QA done The PR has been checked to work properly. and removed needs testing labels Feb 14, 2021

BhaaLseN approved these changes Feb 14, 2021

View reviewed changes

Pokechu22 reviewed Feb 14, 2021

View reviewed changes

Source/Core/Core/IOS/ES/TitleContents.cpp Outdated Show resolved Hide resolved

leoetlino marked this pull request as draft February 15, 2021 00:39

leoetlino force-pushed the es-content-timings branch from 91f30f5 to ed2a712 Compare February 16, 2021 01:10

leoetlino commented Feb 16, 2021

View reviewed changes

Source/Core/Core/IOS/ES/TitleContents.cpp Outdated Show resolved Hide resolved

Source/Core/Core/IOS/ES/TitleContents.cpp Outdated Show resolved Hide resolved

leoetlino force-pushed the es-content-timings branch 2 times, most recently from 766f0c1 to fdd1fc3 Compare February 16, 2021 11:48

leoetlino marked this pull request as ready for review February 16, 2021 11:48

iwubcode reviewed Feb 17, 2021

View reviewed changes

sepalani suggested changes Feb 18, 2021

View reviewed changes

leoetlino force-pushed the es-content-timings branch from fdd1fc3 to 477c847 Compare February 18, 2021 08:28

leoetlino added 5 commits February 18, 2021 18:52

IOS/ES: Log content ID and index when opening contents for debugging

41e2fab

The content ID/index is what actually matters..

IOS/ES: Log content reads for debugging

1073463

We log FS reads already, might as well log ES content reads.

IOS/FS: Allow IPC interface to be used internally from IOS HLE

f214df5

This makes it more convenient to emulate timings for IPC commands that perform internal IOS <-> IOS IPC, for example ES relying on FS for filesystem access.

IOS/ES: Allow various utility functions to return timing info

5eca82a

leoetlino force-pushed the es-content-timings branch from 477c847 to f750208 Compare February 18, 2021 17:54

BhaaLseN reviewed Feb 18, 2021

View reviewed changes

Source/Core/Core/IOS/FS/FileSystemProxy.cpp Outdated Show resolved Hide resolved

IOS: Deduplicate IPC_OVERHEAD_TICKS timing constant

e3bf5fc

leoetlino force-pushed the es-content-timings branch from 93127f2 to e3bf5fc Compare February 18, 2021 20:11

leoetlino merged commit 93f9d67 into dolphin-emu:master Feb 19, 2021
9 checks passed

BhaaLseN mentioned this pull request Feb 20, 2021

Fix IPC_OVERHEAD_TICKS Typo #9525

Closed

IOS: Emulate FS timings for ES content IPC commands #9511

IOS: Emulate FS timings for ES content IPC commands #9511

leoetlino commented Feb 14, 2021

iwubcode commented Feb 14, 2021

JMC47 commented Feb 14, 2021 •

edited

leoetlino commented Feb 14, 2021

BhaaLseN left a comment

JMC47 commented Feb 14, 2021

leoetlino commented Feb 14, 2021

leoetlino commented Feb 15, 2021

leoetlino commented Feb 16, 2021 •

edited

iwubcode Feb 17, 2021

leoetlino Feb 17, 2021

iwubcode Feb 17, 2021

iwubcode Feb 17, 2021

leoetlino Feb 17, 2021

iwubcode Feb 17, 2021

leoetlino Feb 17, 2021

sepalani Feb 18, 2021

leoetlino Feb 18, 2021 •

edited

sepalani Feb 18, 2021

leoetlino Feb 18, 2021

sepalani Feb 18, 2021

leoetlino Feb 18, 2021

sepalani Feb 18, 2021

IOS: Emulate FS timings for ES content IPC commands #9511

IOS: Emulate FS timings for ES content IPC commands #9511

Conversation

leoetlino commented Feb 14, 2021

iwubcode commented Feb 14, 2021

JMC47 commented Feb 14, 2021 • edited

leoetlino commented Feb 14, 2021

BhaaLseN left a comment

Choose a reason for hiding this comment

JMC47 commented Feb 14, 2021

leoetlino commented Feb 14, 2021

leoetlino commented Feb 15, 2021

leoetlino commented Feb 16, 2021 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

leoetlino Feb 18, 2021 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

JMC47 commented Feb 14, 2021 •

edited

leoetlino commented Feb 16, 2021 •

edited

leoetlino Feb 18, 2021 •

edited