Debugging/Logging Techniques for End Users

Question

I searched a bit, but didn't find anything particularly pertinent to my problem - so please do excuse me if I missed something!

A few months back I inherited the source to a fairly-popular indie game project and have been working, along with another developer, on the code-base. We recently made our first release since taking over the development but we're a little stuck.

A few users are experiencing slowdowns/lagging in the current version, as compared to the previous version, and we are not able to reproduce these issues in any of our various development environments (debug, release, different OSes, different machines, etc.). What I'd like to know is how can we go about implementing some form of logging/debugging mechanism into the game, that users can enable and send the reports to us for examination? We're not able to distribute debug binaries using the MSVS 2010 runtimes, due to the licensing - and wouldn't want to, for a variety of reasons.

We'd really like to get to the bottom of this issue, even if just to find out it's nothing to do with our code base but everything to do with their system configuration. At the moment, we just have no leads - and the community isn't a very technically-savvy one, so we're unable to rely on 'expert' bug reports or investigations.

I've seen the debug logging mechanism used in other applications and games for everything from logging simple errors to crash dumps. We're really at a loss at this stage as to how to address these issues, having been over every commit to the repository from the previous to the current version and not finding any real issues.

Answer 1

It sounds like you really want to implement some kind of deployed profiling option, not logging in general (while you could use logging to surface the results of your profile data, logging in general isn't really required here because there are better ways to surface the data).

The basic premise will be to have some fairly lightweight methods/objects you can call or create in your code to track timestamps and shove them into data structure, which you then serialize to disk in some form so that users can email it to you. Something like a BeginTask and EndTask function that takes some kind of task identifier -- a string, or number, or whatever. When BeginTask is called, you can record the current time via a high-resolution counter and store it. Then you do the same in EndTask, except you look for the matching BeginTask timestamp and compute the difference, giving you a task duration.

You can store these in a tree-like structure to give yourself hierarchical profiling (which will help alleviate the issue of coming up with unique task names to match up begin/end pairs). You can also take advantages of C++ idioms such as RAII by putting the calls into the constructor/destructor of some Profile class, then you can simply construct one of these Profile instances in every function that might be time-critical and you'll get the begin/end calls automatically.

You can go even further than that an enable penter and pexit hooks to call your profiler functions for every function in your code automatically, which is a lot less painful than retrofitting construction of Profiler objects everywhere. It will also catch things you might have decided "couldn't be slow" and thus avoided adding Profiler objects to. Unfortunately it's a bit more work to write proper penter/pexit hooks.

Then you can save this information to disk. You could just dump it to a plain-text log file, for simplicity. I find that it's much better to dump the data into a binary format that you can parse back later with a tool on your end -- but if you're not up for writing such a tool, plain text will serve in a pinch. You'll still probably want some code to scan through the data and find the tasks that took the longest and print them outside of the regular call hierarchy, because that's what you're most likely interested in.

Once you have this functionality enabled, you can have users send you their profiling logs and you can hopefully use that to see what is taking up too much time on their machines, and that might help guide your optimization efforts.

We do this kind of instrumentation on our content production tools at work, and dump the statistics into a database which we use to develop daily metrics reports about task performance. Tasks that become outliers in terms of runtime, or take too long on average (especially if they're running on the UI thread) are hilighted in these reports so we know when we accidentally hurt the performance of something.

Answer 2

In my experience relying on users to send you error reports to you even if it's only a push of the button isn't always reliable. Most users won't send these reports, they'll just stop playing and remove the game or app. In most games I've worked on the fraction of users who send bug reports even with a 1-click option is less than 5%, so the subset of users sending you error reports might not be big enough to solve bugs decisively.

It sounds like what would optimally help you here is some kind of tool that would help you take data from all game sessions automatically, aggregate it, and then allow you to look through the aggregated logs for deviations in optimal behavior without relying on the user at all.

Assuming most of your players have an internet connection, what I'd recommend is sending logs to a 3rd party log aggregation tool like Loggly . This way you can send logs from all clients and will have the full set of data from almost all of your users (minus those few who lack internet connection).

As far as what to log, there's a few different ways to go about it

• The approach cited in using penter/pexit hooks is a good one, but I'd recommend instead of saving it to disk that you send it to your logging tool.

• I'd say that you'd want to use a timer or counter to measure the execution time of key functions in any controller classes that are widely consumed by various objects in your game. Things like animation, rendering, AI, UI, or player-character controllers should be measured and then sent as a log if it deviates from what would be considered a normal execution time.

• Along with anything you log, you would want to send all relevant information about the system the user is playing on (like processor, RAM, OS, etc.) as extra data fields with the JSON logs you send.

To actually send the logs, it would be good to implement a separate controller which handles organizing the logs into a JSON that you can easily read and then sending it to the 3rd party provider's logging servers so that it's a simple Logger.log(functionname, executiontime, … [overloaded options you might need] … ) call each time you need to log something.

Over time, this logging will give you constant telemetry for the game which will be immensely useful for logging these bugs and any future ones that may arise.