Profiling your PHP Application

Making an application scale is generally seen as something that only the most magical of developers can do, but it is easy once you have the correct tools. Fortunately for us, these tools are freely available online! In this talk, we will look at a few available options to learn what our applications are actually doing, help identify bottlenecks, and fix them so we can move on to the most important part of any project: delivering features.

Transcript

1. Profiling PHP Michael Heap (@mheap) Developer at DataSift Presented at php|tek, May 2016
2. Me! I’m Michael I’m @mheap Developer at DataSift
3. @mheap https://joind.in/17051
4. Disclaimer
5. Profiling PHP
6. We Won’t Cover Frontend optimisation Database queries TCP Negotiation
7. We Will Cover Quick wins Naive profiling XHProf XHGUI Other considerations
8. Quick Wins Things to do before you start profiling
9. $ php --go-faster
10. $ php --go-faster $ apt-get upgrade php $ yum upgrade php $ pacman -S php
11. Async Workers Gearman Beanstalkd RabbitMQ ZeroMQ
12. Setting the scene
13. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } }
14. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } } [“interaction.content”, “interaction.author.name”]
15. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } }
16. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } }
17. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } }
18. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } }
19. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } }
20. [“interaction.content”] { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } }
21. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } } [“interaction.content”]
22. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } } [“interaction.content”]
23. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } } [“interaction.content”]
24. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } } [“interaction.content”]
25. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } } [“interaction.content”]
26. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } } [“interaction.content”, “interaction.author.name”]
27. { "interaction": { "author": { "id": 115193554, "link": "http://hooliganstsar.tumblr.com/", "username": "hooliganstsar" }, "content": "irhinoceri:\nWhen people try to discount Padme’s love for Anakin they completely ignore the fact that she says “stop come back I love you” even after she realizes that he’s committed murder and that he has delusions of grandeur where they become co-dictators.\nSure, it’s a desperate, emotional plea and not a promise that everything will return to normal. Not saying that. What I am saying is that she still loved him and believed there was good in him even after he destroyed the very republic that s...", "created_at": "Thu, 26 May 2016 15:12:31 +0000", "id": "1e6235444361a9808d6a8de10491c475", "link": "http://hooliganstsar.tumblr.com/post/144958725235", "media_type": "text", "received_at": 1464275553.0978, "schema": { "version": 3 }, "subtype": "post", "type": "tumblr" }, "language": { "tag": "en", "tag_extended": "en", "confidence": 99 }, "salience": { "content": { "entities": [{ "name": "Padme", "type": "Person", "label": "Person", "sentiment": -8, "evidence": 7, "confident": 1, "about": 1, "themes": ["flawed human", "committed murder", "n’t problematic", "justifiably upset", "Dark Side Anakin", "bad meta", "unemotional level", "space feminist", "true reason", "sentient beings", "including children", "political views cause"] }, { "name": "Obi Wan", "type": "Person", "label": "Person", "sentiment": 5, "evidence": 6, "confident": 1, "about": 0, "themes": ["loved Anakin", "Obikin shippers"] }, { "name": "“stop come back I love you”", "type": "Quote", "label": "Quote", "sentiment": 6, "evidence": 1, "confident": 1, "about": 0, "themes": ["committed murder", "emotional plea"] }, { "name": "“well I can respect this woman only if she loves the political system more than the person.”", "type": "Quote", "label": "Quote", "sentiment": 4, "evidence": 1, "confident": 1, "about": 0, "themes": ["political system", "problematic husband ffs", "flawed human", "n’t problematic"] }, { "name": "“space feminist”", "type": "Quote", "label": "Quote", "sentiment": 0, "evidence": 1, "confident": 1, "about": 0, "themes": ["true reason", "bad meta", "unemotional level", "space feminist", "sentient beings", "including children"] }, { "name": "“more.”", "type": "Quote", "label": "Quote", "sentiment": 0, "evidence": 1, "confident": 1, "about": 0, "themes": ["different motivations"] }], "sentiment": 0, "topics": [{ "name": "Crime", "hits": 0, "score": 0.66876006126404, "additional": "irhinoceri: When people try to discount Padme’s love for Anakin they completely ignore the fact that she says “stop come back I love you” even after she realizes that he’s committed murder and that he has delusions of grandeur where they become co-dictators. It’s not like the republic wasn’t problematic itself so basically you’re pitting a flawed human being against a flawed political system and saying “well I can respect this woman only if she loves the political system more than the person.” T..." }] } }, "tumblr": { "action": "create", "activity": "post", "blog": { "id": "115193554", "is_group_blog": false, "name": "hooliganstsar", "url": "http://hooliganstsar.tumblr.com/" }, "blog_name": "hooliganstsar", "blogid": "115193554", "body": "irhinoceri:\n\nWhen people try to discount Padme’s love for Anakin they completely ignore the fact that she says “stop come back I love you” even after she realizes that he’s committed murder and that he has delusions of grandeur where they become co-dictators.\nSure, it’s a desperate, emotional plea and not a promise that everything will return to normal. Not saying that. What I am saying is that she still loved him and believed there was good in him even after he destroyed the very republic that ...", "created_at": "Thu, 26 May 2016 15:12:31 +0000", "format": "html", "id": "000533c038212bbbfd64395be146f382", "is_submission": false, "note_count": 397, "post": { "id": "144958725235", "url": "http://hooliganstsar.tumblr.com/post/144958725235" }, "post_url": "http://hooliganstsar.tumblr.com/post/144958725235", "postid": "144958725235", "reblogged": { "parent": { "blogid": "44626114", "id": "144958505451", "name": "imaginal", "url": "http://imaginal.tumblr.com/post/144958505451" }, "root": { "blogid": "23604722", "id": "140021104712", "name": "irhinoceri", "url": "http://irhinoceri.tumblr.com/post/140021104712" }, "source": { "blogid": "115193554" } }, "short_url": "https://tmblr.co/ZgfWkr270Dfnp", "slug": "irhinoceri-when-people-try-to-discount-padmes", "source_title": "irhinoceri", "source_url": "http://irhinoceri.tumblr.com/post/140021104712/when-people-try-to-discount-padmes-love-for", "type": "text", "url": "https://tmblr.co/ZgfWkr270Dfnp" } }
28. Time limited Resource limited Fixed amount of data
29. Test harness
30. Example data
31. $start = microtime(true); $input = file_get_contents('./small.json'); foreach (explode("\n", $input) as $line){ $tmp = json_decode($line, true); if ($tmp) { $data[] = $tmp; } } echo "Took: ". (microtime(true) - $start);
32. $start = microtime(true); $input = file_get_contents('./small.json'); foreach (explode("\n", $input) as $line){ $tmp = json_decode($line, true); if ($tmp) { $data[] = $tmp; } } echo "Took: ". (microtime(true) - $start);
33. $start = microtime(true); $input = file_get_contents('./small.json'); foreach (explode("\n", $input) as $line){ $tmp = json_decode($line, true); if ($tmp) { $data[] = $tmp; } } echo "Took: ". (microtime(true) - $start);
34. $start = microtime(true); $input = file_get_contents('./small.json'); foreach (explode("\n", $input) as $line){ $tmp = json_decode($line, true); if ($tmp) { $data[] = $tmp; } } echo "Took: ". (microtime(true) - $start);
35. $start = microtime(true); $input = file_get_contents('./small.json'); foreach (explode("\n", $input) as $line){ $tmp = json_decode($line, true); if ($tmp) { $data[] = $tmp; } } echo "Took: ". (microtime(true) - $start);
36. Run Times 50,000 items: 5.7440850734711 50,000 items: 5.8537809848785 50,000 items: 5.5094730854034 50,000 items: 5.8217489719391 50,000 items: 5.8287329673767
37. $start = microtime(true); $input = file_get_contents('./small.json'); foreach (explode("\n", $input) as $line){ $tmp = json_decode($line, true); if ($tmp) { $data[] = $tmp; } } echo "Took: ". (microtime(true) - $start);
38. $start = microtime(true); $input = file_get_contents('./small.json'); foreach (explode("\n", $input) as $line){ $tmp = json_decode($line, true); if ($tmp) { $data[] = $tmp; } } echo "Took: ". (microtime(true) - $start);
39. if (file_exists("./cache")){ $data = json_decode( file_get_contents("./cache"), true ); } else { $input = file_get_contents('./small.json'); foreach (explode("\n", $input) as $line){ // Decode and add to array } file_put_contents("./cache", json_encode($data) ); }
40. Run Times Without Cache: 11.717740058899 With Cache: 8.7964880466461
41. Guessing
42. XHProf sudo pecl install xhprof-0.9.4 extension=xhprof.so /usr/share/php/xhprof_lib
43. xhprof_enable( XHPROF_FLAGS_CPU + XHPROF_FLAGS_MEMORY )
44. $data = xhprof_disable(); print_r($data);
45. [main()==>json_decode] => Array ( [ct] => 50001 [wt] => 4379326 [cpu] => 4710383 [mu] => 807834192 [pmu] => 807572808 )
46. include_once '/usr/share/php/xhprof_lib/utils/ xhprof_lib.php'; include_once '/usr/share/php/xhprof_lib/utils/ xhprof_runs.php'; $runs = new XHProfRuns_Default(); $runs->save_run($xhprof_data, "michael");
47. No Cache
48. Total Incl. Wall Time (microsec): 12,638,896 microsecs Total Incl. CPU (microsecs): 9,692,792 microsecs Total Incl. MemUse (bytes): 929,483,336 bytes Total Incl. PeakMemUse (bytes): 1,170,441,880 bytes Number of Function Calls: 50,008 No Cache
49. Total Incl. Wall Time (microsec): 9,473,467 microsecs Total Incl. CPU (microsecs): 7,010,122 microsecs Total Incl. MemUse (bytes): 815,163,360 bytes Total Incl. PeakMemUse (bytes): 935,510,968 bytes Number of Function Calls: 5 Cache
50. No Cache
51. No Cache
52. No Cache
53. No Cache Cache
54. Back to the task
55. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } } [“interaction.content”, “interaction.author.name”]
56. Version 1
57. public function generate($interaction, $parents = []) { $keys = []; foreach ($interaction as $k => $v) { $newFields = []; if (!is_numeric($k)) { $newFields[] = $k; } if (is_array($v) || is_object($v)) { $keys = array_merge($keys, $this->generate($v, array_merge($parents, $newFields))); } else { $keys[] = implode(array_merge($parents ,$newFields), "."); } } return $keys; }
58. public function generate($interaction, $parents = []) { $keys = []; foreach ($interaction as $k => $v) { $newFields = []; if (!is_numeric($k)) { $newFields[] = $k; } if (is_array($v) || is_object($v)) { $keys = array_merge($keys, $this->generate($v, array_merge($parents, $newFields))); } else { $keys[] = implode(array_merge($parents ,$newFields), "."); } } return $keys; }
59. public function generate($interaction, $parents = []) { $keys = []; foreach ($interaction as $k => $v) { $newFields = []; if (!is_numeric($k)) { $newFields[] = $k; } if (is_array($v) || is_object($v)) { $keys = array_merge($keys, $this->generate($v, array_merge($parents, $newFields))); } else { $keys[] = implode(array_merge($parents ,$newFields), "."); } } return $keys; }
60. public function generate($interaction, $parents = []) { $keys = []; foreach ($interaction as $k => $v) { $newFields = []; if (!is_numeric($k)) { $newFields[] = $k; } if (is_array($v) || is_object($v)) { $keys = array_merge($keys, $this->generate($v, array_merge($parents, $newFields))); } else { $keys[] = implode(array_merge($parents ,$newFields), "."); } } return $keys; }
61. public function generateAll($interactions) { $all = []; foreach ($interactions as $i) { $all = array_merge($all, $this->generate($i)); } return array_filter(array_unique($all)); }
62. public function generateAll($interactions) { $all = []; foreach ($interactions as $i) { $all = array_merge($all, $this->generate($i)); } return array_filter(array_unique($all)); }
63. public function generateAll($interactions) { $all = []; foreach ($interactions as $i) { $all = array_merge($all, $this->generate($i)); } return array_filter(array_unique($all)); }
64. Total Incl. Wall Time (microsec): 8,046,823 microsecs Total Incl. CPU (microsecs): 8,018,211 microsecs Total Incl. MemUse (bytes): 19,617,760 bytes Total Incl. PeakMemUse (bytes): 37,543,384 bytes Number of Function Calls: 355,764
65. public function generate($interaction, $parents = []) { $keys = []; foreach ($interaction as $k => $v) { $newFields = []; if (!is_numeric($k)) { $newFields[] = $k; } if (is_array($v) || is_object($v)) { $keys = array_merge($keys, $this->generate($v, array_merge($parents, $newFields))); } else { $keys[] = implode(array_merge($parents ,$newFields), "."); } } return $keys; }
68. Version 2
69. public function generate($interaction, $parents = []) { $keys = []; foreach ($interaction as $k => $v) { $newFields = []; if (!is_numeric($k)) { $newFields[] = $k; } if (is_array($v) || is_object($v)) { $keys = array_merge($keys, $this->generate($v, array_merge($parents, $newFields))); } else { $keys[] = implode(array_merge($parents ,$newFields), "."); } } return $keys; }
70. public function generate($interaction, $parents = []) { $keys = []; foreach ($interaction as $k => $v) { $newFields = []; if (!is_numeric($k)) { $newFields[] = $k; } if (is_array($v) || is_object($v)) { $keys = array_merge($keys, $this->generate($v, array_merge($parents, $newFields))); } else { $keys[] = implode(array_merge($parents ,$newFields), "."); } } return $keys; }
71. public function generate($interaction, $parents = []) { $keys = []; foreach ($interaction as $k => $v) { $newFields = []; if (!is_numeric($k)) { $newFields[] = $k; } if (is_array($v) || is_object($v)) { foreach ($this->generate($v, array_merge($parents, $newFields) as $val) { $keys[] = $val; } } else { $keys[] = implode(array_merge($parents ,$newFields), "."); } } return $keys; }
72. public function generateAll($interactions) { $all = []; foreach ($interactions as $i) { $all = array_merge($all, $this->generate($i)); } return array_filter(array_unique($all)); }
73. public function generateAll($interactions) { $all = []; foreach ($interactions as $i) { foreach ($this->generate($i) as $g){ $all[] = $g; } } return array_filter(array_unique($all)); }
74. Total Incl. Wall Time (microsec): 3,617,157 microsecs Total Incl. CPU (microsecs): 3,539,472 microsecs Total Incl. MemUse (bytes): 20,135,232 bytes Total Incl. PeakMemUse (bytes): 37,407,936 bytes Number of Function Calls: 334,278
77. Version 2.5
78. public function generate($interaction, $parents = []) { $keys = []; foreach ($interaction as $k => $v) { $newFields = []; if (!is_numeric($k)) { $newFields[] = $k; } if ($v instanceof Traversable) { foreach ($this->generate($v, array_merge($parents, $newFields) as $val) { $keys[] = $val; } } else { $keys[] = implode(array_merge($parents ,$newFields), "."); } } return $keys; }
79. Total Incl. Wall Time (microsec): 274,998 microsecs Total Incl. CPU (microsecs): 221,910 microsecs Total Incl. MemUse (bytes): 19,510,464 bytes Total Incl. PeakMemUse (bytes): 22,173,048 bytes Number of Function Calls: 10,922
80. Version 3
81. public function generate($interaction, $parents = []) { $keys = []; foreach ($interaction as $k => $v) { $newFields = []; if (!is_numeric($k)) { $newFields[] = $k; } if (is_array($v) || is_object($v)) { foreach ($this->generate($v, array_merge($parents, $newFields) as $val) { $keys[] = $val; } } else { $keys[] = implode(array_merge($parents ,$newFields), "."); } } return $keys; }
82. public function generate($interaction, $parents = []) { $keys = []; foreach ($interaction as $k => $v) { $newFields = []; if (!is_numeric($k)) { $newFields[] = $k; } if (!is_scalar($v)) { foreach ($this->generate($v, array_merge($parents, $newFields) as $val) { $keys[] = $val; } } else { $keys[] = implode(array_merge($parents ,$newFields), "."); } } return $keys; }
83. Total Incl. Wall Time (microsec): 2,926,818 microsecs Total Incl. CPU (microsecs): 2,857,804 microsecs Total Incl. MemUse (bytes): 20,126,960 bytes Total Incl. PeakMemUse (bytes): 37,362,384 bytes Number of Function Calls: 284,214
84. Total Incl. Wall Time (microsec): 3,617,157 microsecs Total Incl. CPU (microsecs): 3,539,472 microsecs Total Incl. MemUse (bytes): 20,135,232 bytes Total Incl. PeakMemUse (bytes): 37,407,936 bytes Number of Function Calls: 334,278
85. Total Incl. Wall Time (microsec): 2,926,818 microsecs Total Incl. CPU (microsecs): 2,857,804 microsecs Total Incl. MemUse (bytes): 20,126,960 bytes Total Incl. PeakMemUse (bytes): 37,362,384 bytes Number of Function Calls: 284,214
86. Version 4
87. Total Incl. Wall Time (microsec): 8,046,823 microsecs Total Incl. CPU (microsecs): 8,018,211 microsecs Total Incl. MemUse (bytes): 19,617,760 bytes Total Incl. PeakMemUse (bytes): 37,543,384 bytes Number of Function Calls: 355,764
88. Total Incl. Wall Time (microsec): 1,274,903 microsecs Total Incl. CPU (microsecs): 1,195,136 microsecs Total Incl. MemUse (bytes): 20,086,232 bytes Total Incl. PeakMemUse (bytes): 34,597,576 bytes Number of Function Calls: 93,053
89. $currentDepth = []; foreach($parents as $x){ $currentDepth[] = $x; } foreach($newFields as $x){ $currentDepth[] = $x; }
90. $xx = \gettype($v)[0]; if ($xx == 'a' || $xx == 'o') {
91. The UI
96. XHGui
101. blackfire.io
108. XDebug/Cachegrind tideways.io New Relic Zend Z-Ray PHP Bench Other Tools
109. Observer effect
110. Optimisation
111. Caching The fastest code is code that doesn't run
112. Should it run? The fastest code is code that doesn't run
113. Measuring Production Enable 1 in 1000 requests (XHProf) Blackfire production mode (untested)
114. Logging Work out which code paths are popular Optimise them
115. Used/available memory Response time Timeout Successful/failed requests Open socket count Bandwidth usage Track Everything
116. Considerations Cache stampedes Circuit breakers
117. Measure Refactor Measure again Process
118. “Without measurements, you’re just guessing”
119. Is it worth it?
120. Usually, no
121. Thanks! I’ve been @mheap, you’ve been awesome. Please leave feedback on Joind.in https://joind.in/17051