Upgrade to Pro — share decks privately, control downloads, hide ads and more …

Profiling PHP Applications - Midwest PHP 217

Profiling PHP Applications - Midwest PHP 217

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.

Bbf9decfbfc2ab5b450ec503749ded28?s=128

Michael Heap

March 17, 2017
Tweet

More Decks by Michael Heap

Other Decks in Technology

Transcript

  1. Profiling PHP Michael Heap (@mheap) Freelance at Intechrity Presented at

    Midwest PHP 2017
  2. Me! I’m Michael I’m @mheap Freelance at Intechrity

  3. Me! I’m Michael I’m @mheap Used to work at DataSift

  4. @mheap https://joind.in/20314

  5. Disclaimer

  6. Profiling PHP

  7. Profiling Applications

  8. We Won’t Cover Frontend optimisation Database queries TCP Negotiation

  9. We Will Cover Naive profiling XHProf XHGUI Other considerations

  10. Setting the scene

  11. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael"

    } } }
  12. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael"

    } } } [“interaction.content”, “interaction.author.name”]
  13. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael"

    } } }
  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”] { “interaction”: { “content": "Hello World”, ”author”: { “name”:

    ”Michael" } } }
  19. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael"

    } } } [“interaction.content”]
  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”, “interaction.author.name”]
  25. { "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" } }
  26. Time limited Resource limited Fixed amount of data

  27. Test harness

  28. Example data

  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. $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. 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
  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. $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);
  37. 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) ); }
  38. Run Times Without Cache: 11.717740058899 With Cache: 8.7964880466461

  39. Run Times Without Cache: 11.717740058899 ~5.7 With Cache: 8.7964880466461

  40. Guessing

  41. XHProf sudo pecl install xhprof-0.9.4 extension=xhprof.so /usr/share/php/xhprof_lib

  42. xhprof_enable( XHPROF_FLAGS_CPU + XHPROF_FLAGS_MEMORY )

  43. $data = xhprof_disable(); print_r($data);

  44. [main()==>json_decode] => Array ( [ct] => 50001 [wt] => 4379326

    [cpu] => 4710383 [mu] => 807834192 [pmu] => 807572808 )
  45. 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");
  46. No Cache

  47. 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
  48. 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
  49. No Cache

  50. No Cache

  51. No Cache

  52. No Cache Cache

  53. Back to the task

  54. { “interaction”: { “content": "Hello World”, ”author”: { “name”: ”Michael"

    } } } [“interaction.content”, “interaction.author.name”]
  55. Tests!

  56. public function providerGenerate() { $r = []; $r['two values, same

    namespace'] = [ ['interaction' => ['author' => 'Michael', 'content' => 'Foo' ]], ['interaction.author', 'interaction.content'] ]; $r['multiple levels'] = [ ['interaction' => ['author' => ['name' =>'Michael'], 'content' => 'Foo' ]], ['interaction.author.name', 'interaction.content'] ]; $r['list'] = [ ['interaction' => ['author' => 'Michael', 'content' => ['a','b','c'] ]], ['interaction.author', 'interaction.content'] ]; return $r; }
  57. /** * @dataProvider providerGenerate */ public function testGenerateV1($input, $expected) {

    $r = new \Target\V1(); $actual = $r->generateAll([$input]); $this->assertEquals($expected, $actual); }
  58. Version 1

  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 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; }
  62. 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; }
  63. public function generateAll($interactions) { $all = []; foreach ($interactions as

    $i) { $all = array_merge($all, $this->generate($i)); } return array_filter(array_unique($all)); }
  64. public function generateAll($interactions) { $all = []; foreach ($interactions as

    $i) { $all = array_merge($all, $this->generate($i)); } return array_filter(array_unique($all)); }
  65. public function generateAll($interactions) { $all = []; foreach ($interactions as

    $i) { $all = array_merge($all, $this->generate($i)); } return array_filter(array_unique($all)); }
  66. 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
  67. 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. None
  69. None
  70. function array_merge($a, $b) { $n = []; foreach ($a as

    $v) { $n[] = $v; } foreach ($b as $v) { $n[] = $v; } return $n; }
  71. Run # A B Total Copies 1 0 150 150

    2 150 150 300 3 300 150 450 10 1350 150 1500 1000 149,850 150 150,000 10,000 1,498,500 150 1,500,000 100,000 14,985,000 150 15,000,000
  72. Version 2

  73. 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; }
  74. 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; }
  75. public function generateAll($interactions) { $all = []; foreach ($interactions as

    $i) { $all = array_merge($all, $this->generate($i)); } return array_filter(array_unique($all)); }
  76. public function generateAll($interactions) { $all = []; foreach ($interactions as

    $i) { foreach ($this->generate($i) as $g){ $all[] = $g; } } return array_filter(array_unique($all)); }
  77. 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
  78. None
  79. None
  80. Version 2.5

  81. 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; }
  82. 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
  83. Version 3

  84. 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; }
  85. 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; }
  86. 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
  87. 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
  88. 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
  89. Version 4

  90. 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
  91. 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
  92. $currentDepth = []; foreach($parents as $x){ $currentDepth[] = $x; }

    foreach($newFields as $x){ $currentDepth[] = $x; }
  93. $str = ''; foreach ($currentDepth as $cd) { $str .=

    $cd.'.'; } $keys[] = rtrim($str, ".");
  94. $xx = \gettype($v)[0]; if ($xx == 'a' || $xx ==

    'o') {
  95. Version 5 (PHP 7.1 only)

  96. 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; }
  97. public function generate($interaction, $parents = []) { $keys = [];

    foreach ($interaction as $k => $v) { $newFields = []; if (!is_numeric($k)) { $newFields[] = $k; } if (is_iterable($v)) { foreach ($this->generate($v, array_merge($parents, $newFields) as $val) { $keys[] = $val; } } else { $keys[] = implode(array_merge($parents ,$newFields), "."); } } return $keys; }
  98. Timings here would be unfair as PHP7 is much faster

    (We’ll cover this soon) Long story short: `is_iterable` is not much faster than `is_array || is_object`
  99. function is_iterable($o) { return is_array($v) || is_object($v); }

  100. XHProf UI

  101. None
  102. None
  103. None
  104. None
  105. XHGui

  106. None
  107. None
  108. None
  109. None
  110. None
  111. None
  112. blackfire.io

  113. None
  114. None
  115. None
  116. None
  117. None
  118. None
  119. None
  120. None
  121. Production friendly

  122. Read more https://www.colinodell.com/blog/2015-11/ optimizing-league-commonmark-blackfire-io

  123. XDebug/Cachegrind tideways.io New Relic Zend Z-Ray PHP Bench Other Tools

  124. Observer effect

  125. Application Optimisation

  126. $ php --go-faster

  127. $ php --go-faster $ apt-get upgrade php $ yum upgrade

    php $ pacman -S php
  128. PHP 5.6 PHP 7 Speed Increase V1 8,046,823 2,182,296 72%

    V2 3,617,157 1,278,880 65% V3 2,926,818 1,144,317 61% V4 1,274,903 479,860 62%
  129. Caching The fastest code is code that doesn't run

  130. Should it run? The fastest code is code that doesn't

    run
  131. Async Workers Gearman Beanstalkd RabbitMQ ZeroMQ

  132. Logging Work out which code paths are popular Optimise them

  133. Measuring Production Enable 1 in 1000 requests with XHProf Blackfire

    production mode (with header)
  134. Used/available memory Response time Timeout Successful/failed requests Open socket count

    Bandwidth usage Track Everything
  135. Profile Everything Framework bootstrapping Business logic Unit tests

  136. Measure Refactor Measure again Process

  137. “Without measurements, you’re just guessing”

  138. Is it worth it?

  139. Usually, no

  140. None
  141. Thanks! I’ve been @mheap, you’ve been awesome. Please leave feedback

    on Joind.in https://joind.in/20314