[James Ross]

gpz, on 25 July 2013 - 04:15 AM, said:

Well, I'm afraid not. So it must be something else.

Stack trace from X.1697 using dotTrace Performance (profiler):

FileStream..ctor  •  0 ms  •  3 calls  •  System.IO.FileStream..ctor(String, FileMode, FileAccess, FileShare)
  100.00%   Open  •  System.IO.File.Open(String, FileMode, FileAccess, FileShare)
    100.00%   ParseWAV  •  ORTS.WaveFileData.ParseWAV(String)
      100.00%   OpenWavFile  •  ORTS.WaveFileData.OpenWavFile(String, Int32[]&, Int32[]&, Boolean, Boolean)
        100.00%   SoundPiece..ctor  •  ORTS.SoundPiece..ctor(String, Boolean, Boolean)
          100.00%   SetPiece  •  ORTS.SoundItem.SetPiece(String, Boolean, Boolean)
            100.00%   Queue  •  ORTS.ALSoundSource.Queue(String, PlayMode, Boolean, Boolean)
              100.00%   Run  •  ORTS.ORTSPlayOneShot.Run
                100.00%   HandleEvent  •  ORTS.ORTSDiscreteTrigger.HandleEvent(Event)
                  100.00%   SignalEvent  •  ORTS.MSTSWagon.SignalEvent(Event)
                    100.00%   SignalEvent  •  0 ms of 0  •  ORTS.MSTSLocomotive.SignalEvent(Event)
                      33.55%   StartThrottleIncrease  •  0 ms of 0  •  1 call of 3  •  ORTS.MSTSLocomotive.StartThrottleIncrease
                        33.55%   StartThrottleIncrease  •  ORTS.MSTSLocomotiveViewer.StartThrottleIncrease
                          33.55%   HandleUserInput  •  ORTS.MSTSLocomotiveViewer.HandleUserInput(ElapsedTime)
                            33.55%   HandleUserInput  •  ORTS.MSTSDieselLocomotiveViewer.HandleUserInput(ElapsedTime)
                              33.55%   HandleUserInput  •  ORTS.Viewer3D.HandleUserInput(ElapsedTime)
                                33.55%   Update  •  ORTS.Viewer3D.Update(Single, RenderFrame)
                                  33.55%   Update  •  ORTS.UpdaterProcess.Update
                                    33.55%   DoUpdate  •  ORTS.UpdaterProcess.DoUpdate
                                      33.55%   UpdaterThread  •  ORTS.UpdaterProcess.UpdaterThread
                                        33.55%   ThreadStart_Context  •  System.Threading.ThreadHelper.ThreadStart_Context(Object)
                                           Thread "Updater Process"
                      33.37%   SetDirection  •  0 ms of 0  •  1 call of 3  •  ORTS.MSTSLocomotive.SetDirection(Direction)
                        33.37%   StartReverseIncrease  •  ORTS.MSTSLocomotive.StartReverseIncrease(Nullable[Single])
                          33.37%   Redo  •  ORTS.ReverserCommand.Redo
                            33.37%   ReverserCommand..ctor  •  ORTS.ReverserCommand..ctor(CommandLog, Boolean)
                              33.37%   ReverserControlForwards  •  ORTS.MSTSLocomotiveViewer.ReverserControlForwards
                                33.37%   HandleUserInput  •  ORTS.MSTSLocomotiveViewer.HandleUserInput(ElapsedTime)
                                  33.37%   HandleUserInput  •  ORTS.MSTSDieselLocomotiveViewer.HandleUserInput(ElapsedTime)
                                    33.37%   HandleUserInput  •  ORTS.Viewer3D.HandleUserInput(ElapsedTime)
                                      33.37%   Update  •  ORTS.Viewer3D.Update(Single, RenderFrame)
                                        33.37%   Update  •  ORTS.UpdaterProcess.Update
                                          33.37%   DoUpdate  •  ORTS.UpdaterProcess.DoUpdate
                                            33.37%   UpdaterThread  •  ORTS.UpdaterProcess.UpdaterThread
                                              33.37%   ThreadStart_Context  •  System.Threading.ThreadHelper.ThreadStart_Context(Object)
                                                 Thread "Updater Process"
                      33.08%   StartTrainBrakeDecrease  •  0 ms of 0  •  1 call of 3  •  ORTS.MSTSLocomotive.StartTrainBrakeDecrease(Nullable[Single])
                        33.08%   HandleUserInput  •  ORTS.MSTSLocomotiveViewer.HandleUserInput(ElapsedTime)
                          33.08%   HandleUserInput  •  ORTS.MSTSDieselLocomotiveViewer.HandleUserInput(ElapsedTime)
                            33.08%   HandleUserInput  •  ORTS.Viewer3D.HandleUserInput(ElapsedTime)
                              33.08%   Update  •  ORTS.Viewer3D.Update(Single, RenderFrame)
                                33.08%   Update  •  ORTS.UpdaterProcess.Update
                                  33.08%   DoUpdate  •  ORTS.UpdaterProcess.DoUpdate
                                    33.08%   UpdaterThread  •  ORTS.UpdaterProcess.UpdaterThread
                                      33.08%   ThreadStart_Context  •  System.Threading.ThreadHelper.ThreadStart_Context(Object)
                                         Thread "Updater Process"

Three examples where file access is performed on the Updater Process thread. :thumbup3:

[gpz]

Ah, I see! There is an exception from the sound updating process for discrete triggers! I haven't even realized this till now, but now I see it. The ORTSDiscreteTrigger.HandleEvent() is called from MSTSWagon.

All the other type of triggers have a TryTrigger() method, that is updated during the normal sound update (it is kind of a pull technology :) ), except of the ORTSDiscreteTrigger, which has a HandleEvent(Event) method instead. When an event occurs, the Updater process searches through all SoundStreams for such an eventhandler. ("push technology" :pardon: )

I think a List of events should be maintained instead. The sound process could loop through this list too. The only difficulty is that the Updater process should add elements to this list, while Sound process should remove them. Can it be done by locking this list by both processes while doing operation on it?

[James Ross]

gpz, on 05 August 2013 - 01:36 AM, said:

I think a List of events should be maintained instead. The sound process could loop through this list too. The only difficulty is that the Updater process should add elements to this list, while Sound process should remove them. Can it be done by locking this list by both processes while doing operation on it?

Locking is bad. :)

A relatively simple option is to give one of the classes a new method that sets a Boolean flag to true when the event occurs (instead of directly playing it), and then the sound updater checks the flags, resets them and kicks off the actual playback (in that order). It isn't fool proof, but ought to work well enough for now.

Longer term, we should probably use a lockless list (e.g. using a circular buffer) for this, which will probably be useful in other places too.

[gpz]

Do you mean something like to add a member e.g.

bool[110] EventFlags

to class MSTSWagon, issueing command

EventFlags[(int)evt] = true;

when a particular event occurs, and give a GetEventFlags() method to sound process to use, which also resets all the flags?

[James Ross]

gpz, on 05 August 2013 - 02:46 AM, said:

Do you mean something like to add a member e.g.

bool[110] EventFlags

to class MSTSWagon, issueing command

EventFlags[(int)evt] = true;

when a particular event occurs, and give a GetEventFlags() method to sound process to use, which also resets all the flags?

That's a more brute-force method; I was thinking that ORTSPlayOneShot or similar - so that when the event occurs, you work out which sound is desired - would have a flag (just one Boolean).

[gpz]

Yes, but there might be more than one event at the same time. (An event can trigger an other event, and so on.) So eventually some kind of a list of the currently active events is needed. One single flag is not enough, a list of the occurred events should also be passed. (And at the time of passing, the list also has to be reset.) This list can then be probed at all streams, if any of them is "listening" for any of the events in the list.

[James Ross]

gpz, on 05 August 2013 - 03:32 AM, said:

Yes, but there might be more than one event at the same time. (An event can trigger an other event, and so on.) So eventually some kind of a list of the currently active events is needed.

Yes, that is why I said (emphasis added):

Quote

It isn't fool proof, but ought to work well enough for now.

Longer term, we should probably use a lockless list ...

Are you saying that it doesn't provide any sort of usefulness to flag the sounds as 'triggered'? If so, I'd actually prefer the discrete triggers were just disabled until such time as we have a lockless list of events available.

[gpz]

All right, now I'm starting to understand what you are writing. I think it can be also done, that instead of actually running the SoundCommand.Run(), just flagging it, and letting the sound process to run the sound command.

However this solution implies that the updater process still needs to loop though the list of all SoundSources, and through all the SoundStreams in every SoundSource to find the trigger that needs to be triggered. If we could just pass the actually active events, this whole searching could be done by the sound process, which anyway loops through all of these objects. But otherwise what you propose can be done!

Edit: As I am reading about the multithreading issues on internet, I found out, that looping through the SoundSources and SoundStreams lists by Updater process most probably isn't thread safe as well. (The current code does this too.) What about a solution that MSTSWagon would contain a list of events, that sound process would copy time-by-time, and would only set a "processed" flag for that, which would force MSTSWagon to reset the list before it starts writing it again? In this way only the Updater process would write the list, and Sound process would always know if the list is valid.

[roeter]

Here is some more insight in stuttering etc., using the new graphics info.

First a loader burst, probably loading files for next tile(s) :


The sudden 'burst' in the loader process causes a severe dip in the frame-rate which causes stutter and often leads to wheelslips as well. The whole process seems rather inefficient : loader is doing nothing for most of the time, but the sudden bursts causes jitter in other processes. Could this process be made more efficient by spreading the load somehow?

Next a sound-file loaded for the first time (in this case, horn). It confirms what is stated above.


Regards,

Rob Roeterdink

[James Ross]

roeter, on 05 August 2013 - 05:26 AM, said:

The sudden 'burst' in the loader process causes a severe dip in the frame-rate which causes stutter and often leads to wheelslips as well. The whole process seems rather inefficient : loader is doing nothing for most of the time, but the sudden bursts causes jitter in other processes. Could this process be made more efficient by spreading the load somehow?

That depends on what is delaying the frames. Your graphs do not look like mine, for example, so it is entirely possible that there isn't a single good solution either.

The issue I am most commonly seeing is a single (or, rarely, two) GC spike, indicating a full collection (i.e. gen 0, 1 and 2), and a corresponding single spike in frame time. Not all full collections have a corresponding frame time spike, but during loading it seems more likely. This is something that could be improved simply by moving to a new version of .NET (after disconnecting from XNA). I have not tried the experimental "loading delay" option with the new graphs yet, but I plan to - it could make a difference.

OTOH, your graphs show no full collections, a large cluster of slow frames and a drop in the updater process. The updater process drop is probably just a result of the cluster of slow frames - less frames per second means less updates too. What is causing all the slow frames is not so clear. It could be the cluster of partial collections (gen 0 and 1 only). I need to enhance the GC graph to look further in to that. But it could also be caused by the GPU driver stalling while uploading the new data. I've seen this in profiles before - you create the texture, then on first-use in the render process it hangs for a few ms while the texture is copied from system RAM to VRAM. This was actually what my experimental "loading delay" option was designed for. However, it would only help if the driver was uploading the textures anyway - if it was doing on-demand uploads, you're stuck with a pause even if you wait.

Incidentally, the P95 and P99 values in the FPS line are what we should use to compare different systems level of stuttering. Record the worst values seen over the loading period (it is using 10s of data).