Performance: Music Playing, Event Manager, and Generate Text

So, I’m currently investigating a reliable lag-spike in my project, and I’m finding that a few different things seem to be contributing to it. In this thread I’d like to ask after three of those things (the remainder being still under investigation):

In the relevant period as reported by PStats, I’m seeing a spike in all three of these, to the following values:

  • Event Manager: ~19ms
  • Generate Text: ~23ms
  • AudioSound.play (recorded via a custom PStats collector): ~51/52ms(!)

Now, text has long been slow to generate–but I’ll confess that I’m still a little surprised at how large is its spike here. Is there anything that I might do to mitigate it…? (Aside from pre-generating my text, which I’d rather avoid.)

As to the Event Manager… What might cause that…? I really don’t know where to begin with this one…

And finally… Why might the playing of an AudioSound be so slow…? A few points that might be relevant:

  • This is music that’s being played, not a sound-effect
  • The relevant AudioSound is already loaded, and is reported to be in the “READY” state
  • I’ve set the number of concurrent sounds in the music-manager to 2
    • This in order that I can fade out the previous music when I start a new piece
      • However, note that testing seems to suggest that the fading code is not (directly) the cause of the spike
  • I’m using the OpenAL back-end
    • (And thus an “OpenALAudioSound” object, specifically)

Does anyone have any insight on these spikes?

I have some guesses about music, I know it’s a streaming technology, so the problem may be the speed of access to the hard drive.

It could be: I don’t have an SSD, if I’m not much mistaken. And if the spike is going to be significantly lessened on more-recent machines than mine, then it might not be too bad.

Still… fifty-odd milliseconds feels like quite a large jump…

As for the text, I don’t see any inconvenience in its preliminary creation. Moreover, if the text is static during the entire period of run of the application. This is actually a good option to solve.

It’s just an awful lot to pre-create, I feel.

If I had only one or two text-strings, then absolutely: I likely would create then on startup and have done with it. But I have a fair few strings, I fear.

I could look into the feasibility of pre-creating a limited sub-set, I suppose…

How much text are you generating exactly? Does your text have fancy features, like embedded text glyphs, or a lot of markup? There have been substantial optimizations to the text generation recently, but it’s possible that a certain path is a bit slow, if you can isolate the specific inputs that cause this slowness perhaps I could optimize it.

There are a few things you can look at to make text generation faster, described on this page:

https://docs.panda3d.org/1.10/cpp/optimization/performance-issues/too-many-text-updates

AudioSound.play is strange. That’s not supposed to take long. Same with EventManager. It’d be worth diving a little deeper - like checking how many events are being generated, or which specific call with pstats-python-profiler 1.

In this specific instance, not a lot: a single line. (Unless I’m inadvertently doing more than I intend.)

In the game overall, a fair bit–I don’t have a full count, but I have a number of “toml” files, many of which contain a number of entries.

I… Honestly wasn’t aware that we had markup functionality. ^^;

More to the point, the one feature that I am using is an outline. I’m also setting the point-size, line-height, space-advance, and background-colour.

Based on some testing, it looks like it’s a combination of the point-size and outline:
In today’s testing:

  • With all of the above settings, I get a spike of ~23ms
  • With none of the above settings, I get a “spike” of ~1.4ms
  • With no outline, I get a spike of ~4.3ms
  • With no point-size, I get a spike of ~3.7ms
  • With neither outline nor point-size, I get a “spike” of ~2ms
  • With point-size and outline, but none of the other settings, I get a spike of ~23ms

Which would seem to be a trouble, as I’m using the outline feature to create nicely-outlined text that (A) looks good and (B) is visible on a variety of backgrounds.

That said, it is possible that I could reduce the point-size: I imagine that I applied that setting in order to get nice crisp text–but as I’m using the same value for much larger text elsewhere, I may well be overdoing it for this text.

Thank you for that! :slight_smile:

Hmm… Setting the “text-page-size 512 512” option does bring the spike down to ~12ms, so that’s tempting.

(I’m not sure that the removal of text-flattening is likely to be helpful in my case, and I’m hesitant to try it.)

A good thought!

(For any reading this in the future, let me clarify that the config variable is the other way around: “pstats-python-profiler 1”.)

But oof, the performance impact of the Python profiler! o_o What do you have against my poor computer, rdb?! XD;

As to the results, it indicated… just AudioSound->play. A massive spike in that one place.

As to checking how many events are being generated, how might I do that? I don’t see a likely config-variable or PStats collector, offhand.

I tried “notify-level-event spam”, which, well, spams events–it’s hard to be sure of what’s happening quite when. I also tried “notify-level-EventManager spam”–but it seemed to produce no output.

I did try “pstats-eventmanager 1”, and it seems to be indicating a lot of time in an event called “player”.

Now, my player-character’s collider is named “player”, and the issue comes up on collecting an item–something that is done via collision. (Using Panda’s built-in collision system.)

So I’m wondering whether perhaps I’m getting lots of collisions for some reason–the object with which the player collides in this matter should be being removed as a result, but perhaps it’s happening too late?

Perhaps, then, that’s causing the associated sound to likewise be played many times over–thus resulting in a spike in both events and audio-playing…

It’s something to investigate, at least!

[edit]
Update: I don’t seem to be finding multiple player-involved collision-events as I’d speculated.

I did find a recurring redundant collision–and object that was essentially colliding with itself, due to having two colliders that shared a bit–which I’ve rectified. However, it seems to have been pretty much harmless, and the fix doesn’t seem to have changed the “player” section of the event-manager reporting.

(Which makes sense, as it didn’t involve the player.)

https://docs.panda3d.org/1.10/python/programming/gui/embedded-text-properties

Please file a bug report with a minimal test case that demonstrates this - maybe it’s easy to optimize and I can still get this change into the next minor release. This is a ridiculous amount of time for text generation.

Oh yes, especially with outlines, this will definitely be an issue! And with a higher point size, Panda is very quickly going to run out of space on a text page, so larger text pages would also help.

You can just make a copy of the font object with a different point size.

It won’t make your computer explode - it’s worth a try? Text flattening is a lot less useful since the text optimizations in 1.10.0.

base.messenger.toggleVerbose()

I guess we need a C++ profiler to dig deeper. If you can create a repro case, or isolate it to a specific sound file, this might be useful. If the method is just being called very often, that would certainly explain it.

Huh, interesting. I wonder if this is due to something generating a lot of Python calls (which could be a red flag) or just that you’re using a 1.10 build, since the master build of Panda contains optimizations for passing a large amount of PStats data more efficiently.

Ah, that is cool! :slight_smile:

All right, just halving my point-size and making related changes to the outline parameters and the size of the text has produced a significant reduction in the spike associated with “generateText”. Indeed, it’s now down to ~3ms, which I’m quite happy with! :slight_smile:

Happily, it turns out that the font in question was already a copy (having been made, it seems, to provide a thicker outline for smaller text). So that works out nicely! :slight_smile:

As a result, I’m not going to worry about text-flattening (although you do make good points, and I had been ready to try it before the above improvement).

I’m also now not sure that a bug-report is called for–it looks like this may just be a case of excessive parameter-values.

But, if you still want a bug-report, I’m happy to put one together! :slight_smile:

Ahh, right!

All right, I’m… not really seeing that many player-related events: just one each of the following:

  • player-into-item
  • player-into
  • into-item
  • out-of-item
  • player-out-of-item

Which seems about right, to me.

Hmm… Investigating more, it seems like my code is calling “play” about 10 times in the frame in question.

(Once for the “item acquired” sound; once for the item-specific “taken” sound; once for a certain door closing; five times for five enemies spawning (i.e. once per spawn); once for one enemy changing state; and once for a sound that signals the start of combat.)

Is that too many calls for a single frame…?

(I had thought that this was about a music-file playing, but perhaps I was mistaken–perhaps it was about sound-effects…)

It could be either–I am on 1.10, after all. And my computer is likely not the newest thing any more, too. (It’s a Dell laptop, with 4 cores at 2.4GHz and 8GM of RAM.)