Profiling your PHP Application

So, you've been through and changed all your double quotes to single quotes but your application still isn't running at the speed of light. What's going on?

Making an application scale is generally seen as something that only the most magical of developers can do, but it's easy once you have the correct tools. Fortunately for us, these tools are freely available online!

In this talk, we'll take a look at a few options that we have available to work out what our application is actually doing, help identify bottlenecks and fix them so that we can move on to the more important part of the project: delivering features.

Transcript

1. Profiling PHP Michael Heap (@mheap) Developer at DataSift Presented at FOSDEM 2016
2. Me! I’m Michael I’m @mheap Developer at DataSift
3. Disclaimer
4. Profiling PHP
5. We Won't Cover Frontend optimisation Database queries TCP Negotiation
6. We Will Cover Quick wins Naive profiling XHProf XHGUI Other considerations
7. Quick Wins Things to do before you start profiling
8. $ php --go-faster
9. $ php --go-faster $ apt-get upgrade php $ yum upgrade php $ pacman -S php
10. Async Workers Gearman Beanstalkd RabbitMQ ZeroMQ
11. Setting the scene
12. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } }
13. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } } [“interaction.content”, “interaction.author.name”]
14. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } }
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”] { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } }
20. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } } [“interaction.content”]
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”, “interaction.author.name”]
26. Getting Started
27. $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);
28. $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);
29. $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);
30. $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);
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. 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
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. 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) ); }
36. Run Times Without Cache: 11.717740058899 With Cache: 8.7964880466461
37. Guessing
38. XHProf sudo pecl install xhprof-0.9.4 extension=xhprof.so /usr/share/php/xhprof_lib
39. xhprof_enable( XHPROF_FLAGS_CPU + XHPROF_FLAGS_MEMORY )
40. $data = xhprof_disable(); print_r($data);
41. [main()==>json_decode] => Array ( [ct] => 50001 [wt] => 4379326 [cpu] => 4710383 [mu] => 807834192 [pmu] => 807572808 )
42. 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");
43. No Cache
44. 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
45. 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
46. No Cache
47. No Cache
48. No Cache
49. No Cache Cache
50. Back to the task
51. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael" } } } [“interaction.content”, “interaction.author.name”]
52. Version 1
53. 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; }
54. 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; }
55. 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; }
56. 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; }
57. public function generateAll($interactions) { $all = []; foreach ($interactions as $i) { $all = array_merge($all, $this- >generate($i)); } return array_filter(array_unique($all)); }
58. public function generateAll($interactions) { $all = []; foreach ($interactions as $i) { $all = array_merge($all, $this- >generate($i)); } return array_filter(array_unique($all)); }
59. public function generateAll($interactions) { $all = []; foreach ($interactions as $i) { $all = array_merge($all, $this- >generate($i)); } return array_filter(array_unique($all)); }
60. 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
61. 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; }
64. Version 2
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; }
66. 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; }
67. public function generateAll($interactions) { $all = []; foreach ($interactions as $i) { $all = array_merge($all, $this- >generate($i)); } return array_filter(array_unique($all)); }
68. public function generateAll($interactions) { $all = []; foreach ($interactions as $i) { foreach ($this->generate($i) as $g){ $all[] = $g; } } return array_filter(array_unique($all)); }
69. 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
72. Version 2.5
73. 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; }
74. 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
75. Version 3
76. 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; }
77. 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; }
78. 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
79. 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
80. 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
81. Version 4
82. 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
83. 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
84. $currentDepth = []; foreach($parents as $x){ $currentDepth[] = $x; } foreach($newFields as $x){ $currentDepth[] = $x; }
85. $xx = \gettype($v)[0]; if ($xx == 'a' || $xx == 'o') {
86. The UI
91. XHGui
96. blackfire.io
103. Other Tools XDebug/Cachegrind tideways.io New Relic catchy.io PHP Bench
104. Optimisation
105. Caching The fastest code is code that doesn't run
106. Should it run? The fastest code is code that doesn't run
107. Measuring Production Enable 1 in 1000 requests (XHProf) Blackfire production mode (untested)
108. Logging Work out which code paths are popular Optimise them
109. Track Everything Used/available memory Response time Timeout Successful/failed requests Open socket count Bandwidth usage
110. Considerations Cache stampedes Circuit breakers
111. Process Measure Refactor Measure again Without measurements, you're just guessing
112. Is it worth it?
113. Thanks! I’ve been @mheap, you’ve been awesome. Please leave feedback on Joind.in https://joind.in/16814