You can learn a lot about your code by instrumenting it. \u00a0You’ll find methods that are called more than you’re expecting, or be able to identify which part of your code is slowing the app down.<\/p>\n
There are Saas solutions for this, like New Relic. \u00a0From my experience, New Relic “runs” out of the box, and may provide information on common tools (MySQL, etc), but doesn’t provide any real information about your<\/em> app without adding instrumentation calls to your code.<\/p>\n Also, New Relic works on an aggregated summary<\/em> of your application. \u00a0If it supplies details on a specific request<\/em>, I never found it.<\/p>\n If you have to instrument your code, and you want to know exactly what your users are doing, then what’s the appeal of New Relic?<\/p>\n Recently, I was involved with a project to instrument some “under performing” python code. \u00a0New Relic had been installed, but had provided no value.<\/p>\n Caveat: I was involved on the analysis side. \u00a0Another developer wrote the logging framework.<\/p>\n A performance\u00a0class was created and we added a custom django handler<\/a>\u00a0that initialize a performance object for the request.<\/p>\n To instrument a method, you would wrap it in a ‘with’ statement<\/a>:<\/p>\n The ‘with’ syntax provides an __enter__ and __exit__ hook, which was used in the performance class to start and stop a timer for that block of code. \u00a0On __exit__, logging information for this block was added to a data structure for the entire request.<\/p>\n When the request finished, the handler would write the entire logging block using the standard logging mechanism. \u00a0Log these at DEBUG and it was easy to disable it in production.<\/p>\n What you ended up with was a nested set of performance information:<\/p>\n You could now see that “mysql user lookup” was called twice (!), and was responsible for 95%\u00a0of time spent (!). \u00a0Even better, you knew this information for this individual request<\/em>. \u00a0You can summarize the performance of these blocks across the system (ala New Relic), but you could also zoom in and see the details for this particular user. \u00a0Powerful stuff, right?<\/p>\n With your own code, the possibilities are limitless. \u00a0In a web app environment, maybe the page is authenticated. \u00a0Add the user’s ID to the logging block, and now you can see exactly what happened<\/em> for Mary<\/em> on Tuesday<\/em> at 10AM<\/em>. \u00a0If you run multiple applications or subsystems, add their identifiers to the logs and you can break performance out by component.<\/p>\n Once the information was written to the logs, it was loaded into an Elasticsearch<\/a>\u00a0cluster for analysis.<\/p>\n With all of this data, the next step is to see what’s going on. \u00a0The ELK environment has come a long way since in the year since this project, so it would probably be even easier now!<\/p>\n With the data properly loaded parsed in\u00a0logstash and fed into elasticsearch, you can make dashboards in kibana to show things like:<\/p>\n We found it to be very useful to wrap every third-party API call with this framework. \u00a0If the vendor was slow, we’d be slow, but now we had our own data to isolate the cause and work with the vendor.<\/p>\n Combine this information with other sources of data and you can determine neat stuff like:<\/p>\n Doing a basic code review on the worst-performing block would usually make it very clear why the performance was suffering. \u00a0I was the largest creator of tickets for the dev group in the company.<\/p>\n Using this information, we focused on two goals:<\/p>\n We were very successful in both of these goals.<\/p>\n We had several interesting “deep dives” into this data, but one of them stands out:<\/p>\n The whole system was monitored with Gomez, which one of the executives liked. \u00a0Gomez started to report performance problems, but they weren’t seen in the summary data that we graphed.<\/p>\n Since we had the details, I was able to find the exact request that Gomez had made (user name and time), and see the block of code that was slow.<\/p>\n It turned out that the system was writing a row into a table every time a user logged in. \u00a0The Gomez test account logged in a lot<\/em>, so there were a lot of rows for this user. \u00a0The application\u00a0pulled these rows, looking for some recent information (last search string, etc). \u00a0Unfortunately, the app pulled in all<\/em> the rows, not the just recent ones that it needed.<\/p>\n It was easy to find and easy to fix. \u00a0Management was happy.<\/p>\n","protected":false},"excerpt":{"rendered":" Application Performance Logging You can learn a lot about your code by instrumenting it. \u00a0You’ll find methods that are called more than you’re expecting, or be able to identify which part of your code is slowing the app down. There … Continue reading with<\/span> performanceTracking(\"block name\"):\r\n some block of code<\/pre>\n{\r\n \"requestid\": \"12345\",\r\n \"name\": \"my web page\",\r\n \"calls\": 1,\r\n \"duration\": 200,\r\n \"children\": [\r\n {\r\n \"calls\": 2,\r\n \"name\": \"mysql user lookup\",\r\n \"duration\": 190\r\n },\r\n {\r\n \"calls\": 1,\r\n \"name\": \"something else\",\r\n \"duration\": 10\r\n }\r\n }\r\n}<\/pre>\nPerformance Analysis<\/h1>\n
\n
\n
\n