Performance Profiling the Unexpected in Node.js

Performance testing a Node.js application can be painful. Tooling can be a nightmare to set-up, and online help is almost non-existent. And even with the perfect setup in place... what are you even supposed to be looking for?

This is the position that we found ourselves in last year at Box, and this talk is the story of everything we've learned since. Instead of listing every relevant tool or teaching you how to setup awesome flame graphs, I'm going to share the surprising and unexpected things we learned about Node.js performance at Box, and how we reduced server response times by over 80% along the way. Sometimes just knowing what to look for is half the battle.

Presented at NodeSummit, 2015
Fonts: Lulo Clean, Avenir, DIN

Transcript

1. Profiling the UNEXPECTED
2. TODAY, I WANT TO TELL YOU A STORY…
3. the flashback
4. B O X 2013
5. B O X M O B I L E S I T E 2013
6. O N E B I G P H P A P P L I C AT I O N M O B I L E S PA G H E T T I B R O K E N C O N T R A C T S W E B A P P A R C H I T E C T U R E C I R C A 2 0 1 3
7. M O D U L A R I Z E T H E M O N O L I T H S T R O N G E R C O N T R A C T S FA S T E R D E V E L O P M E N T A L L J S O N T H E F R O N T- E N D E N T E R N O D E . J S
8. THE MOBILE SITE WAS THE PERFECT EXPERIMENT
10. B O X M O B I L E S I T E 2014
11. OKAY… BUT HOW DOES IT PERFORM?
12. the journey
13. T H E S E T U P MOCKED OUT API (250MS RESPONSE) ACTS AS AN ACTUAL EXTERNAL SERVER SET RESPONSE TIME, VARIANCE, STABILITY
14. T H E S E T U P TESTED WITH APACHE BENCHMARK 20X CONCURRENCY FOCUS ON 50TH PERCENTILE
15. T H E S E T U P TESTED A SINGLE APPLICATION IN REALITY, MANY ON ONE MACHINE
16. M . B O X R E L E A S E C A N D I D A T E 1 . 0 (20X CONCURRENCY)
17. M . B O X R E L E A S E C A N D I D A T E 1 . 0 2533MS (20X CONCURRENCY)
18. 2533ms
19. MaxSockets
20. M A X S O C K E T S “DETERMINES HOW MANY CONCURRENT SOCKETS THE AGENT CAN HAVE OPEN PER ORIGIN” — NODE.JS DOCS
21. M A X S O C K E T S D E FA U LT VA L U E IO.JS? INFINITY NODE V0.12? INFINITY NODE V0.10? …5
22. R E M O V I N G T H E M A X S O C K E T S L I M I T var http = require('http'); http.globalAgent.maxSockets = Infinity; // or… var https = require('https'); https.globalAgent.maxSockets = Infinity;
23. M . B O X R C 1 . 0 . 1 - / W G L O B A L M A X S O C K E T S F I X ~2533MS (20X CONCURRENCY) NO SIGNIFICANT CHANGE
25. TIME SECONDS CALLS SYSCALL ------ ----------- --------- ------------- 44.17 0.003208 3526 EPOLL_WAIT 20.27 0.001472 20037 FUTEX 11.63 0.000845 1363 WRITE 9.42 0.000684 7624 READ $ S T R A C E - C N O D E S E R V E R . J S
26. TIME SECONDS CALLS SYSCALL ------ ----------- --------- ------------- 44.17 0.003208 3526 EPOLL_WAIT 20.27 0.001472 20037 FUTEX 11.63 0.000845 1363 WRITE 9.42 0.000684 7624 READ $ S T R A C E - C N O D E S E R V E R . J S
28. THE API IS ONLY TAKING 250MS…
29. THE API IS ONLY TAKING 250MS… REQUESTS ARE TAKING 10X TOO LONG…
30. THE API IS ONLY TAKING 250MS… REQUESTS ARE TAKING 10X TOO LONG… HALF OF OUR TIME IS SPENT WAITING…
31. THE API IS ONLY TAKING 250MS… REQUESTS ARE TAKING 10X TOO LONG… HALF OF OUR TIME IS SPENT WAITING… REMOVING COMPUTATION DOES NOTHING…
32. THE API IS ONLY TAKING 250MS… REQUESTS ARE TAKING 10X TOO LONG… HALF OF OUR TIME IS SPENT WAITING… REMOVING COMPUTATION DOES NOTHING… THERE HAS TO BE A BOTTLENECK SOMEWHERE…
33. request()
34. #6 MOST RELIED UPON NPM MODULE SIMPLIFIES A TON OF HTTP REQUEST COMPLEXITY FLEXIBLE, A TON OF OPTIONS R E Q U E S T: T H E G O O D
35. R E Q U E S T P O O L I N G ALLOWS YOU TO REUSE AGENTS KEEP CONNECTIONS OPEN ENABLES CONNECTION POOLING
36. R E Q U E S T: T H E P R O B L E M KEEPS ITS OWN CONNECTION POOL BAD DOCUMENTATION (AT THE TIME) CREATED ITS OWN NEW AGENTS AGENT MAXSOCKETS? 5. OF COURSE.
37. R E M O V E C O N N E C T I O N P O O L I N G A L L T O G E T H E R request({ url: 'https://api.box.com/...', method: 'GET', pool: false });
38. R E M O V E T H E M A X S O C K E T S L I M I T var connectionPool = {maxSockets: Infinity} request({ url: 'https://api.box.com/...', method: 'GET', pool: connectionPool });
39. M . B O X R C 1 . 1 - M A X S O C K E T S F I X 1077MS (20X CONCURRENCY) PREVIOUSLY 2533MS 57.5% SPEED UP
40. • DON’T LEAVE PROFILING TO THE LAST MINUTE • USE (AND LEARN) THE TOOLS AT YOUR DISPOSAL • DON'T BE AFRAID TO JUMP IN TO OSS AND HELP • DON'T LEAVE PROBLEMS UNANSWERED K E Y TA K E AWAY S
41. Template caching
42. H A N D L E B A R S <div class="entry"> <h1>{{title}}</h1> <div class="body"> {{body}} </div> </div> var context = { title: "M.Box", body: "Welcome to Box!" }; var html = template(context);
43. H A N D L E B A R S <div class="entry"> <h1>{{title}}</h1> <div class="body"> {{body}} </div> </div> var context = { title: "M.Box", body: "Welcome to Box!" }; var html = template(context); ~20MS <1MS
44. H A N D L E B A R S C A C H I N G SAVE THESE FUNCTIONS FOR LATER MUCH FASTER BUT, CAN’T HOT-RELOAD TEMPLATES
45. M . B O X R C 1 . 2 - T E M P L A T E C A C H I N G F I X 488MS (20X CONCURRENCY) PREVIOUSLY 1077MS 54.7% SPEED UP
46. N O D E . J S B E H A V I O R NODE IS SINGLE THREADED EVENT DRIVEN ASYNCHRONOUS
47. N O D E . J S & T H E E V E N T L O O P ONE LOOP TO RULE THEM ALL WAIT OUTSIDE THE LOOP RETURN TO THE LOOP ON I/O COMPLETION
48. N O D E . J S & T H E E V E N T L O O P & C O M P U TA T I O N COMPUTATION BLOCKS HOLDS UP THE LOOP HOLDS UP OTHER REQUESTS COMPOUNDING
49. • I/O IS INSANELY CHEAP • COMPUTATION IS EXPENSIVE • KNOW THE STRENGTHS & WEAKNESSES OF YOUR ENVIRONMENT K E Y TA K E AWAY S
50. timestamps
51. M O M E N T. J S LESS THAN A MILLISECOND EACH 100 FOR THE ALL FILES PAGE
52. L I B I C U USES NATIVE I18N LOGIC COMPILED INTO THE V8 ENGINE (C++) SUPER FAST
53. L I B I C U SUPPORT ADDED IN V0.11 EXISTS IN CHROME TODAY WITHOUT LIBICU: ~8MS WITH LIBICU: ~2MS
54. • DEATH BY 100 PAPER CUTS • IN HOT CODE PATHS, EVERY MS COUNTS • NATIVE FEATURES CAN HAVE THE 
 OPTIMIZED ADVANTAGE OVER USER-LAND LIBRARIES K E Y TA K E AWAY S
55. profiling cpu
56. W E B K I T- D E V T O O L S - A G E N T NOT EASY TO SET UP HARD TO KEEP A CONNECTION PROTIP: DON’T START SETTING UP AT 4PM ON A FRIDAY
57. C P U A N A LY S I S
58. ( P R O G R A M ) IDLE TIME 93% OF OUR TOTAL TIME
59. U T I L . F O R M A T NICE STRING FORMATTER FOR CONVENIENCE, MOSTLY WASTEFUL IN HOT CODE PATHS
60. G A R B A G E C O L L E C T I O N CAN BE SIGNIFICANT EVENTS BLOCKING! CAN WRECK HAVOC WITH HEALTH CHECKS
61. G A R B A G E C O L L E C T I O N M I T I G A T I O N CONFIGURE SLAB_BUFFER_SIZE SMALLER, MORE FREQUENT CLEANUP
62. • UNDERSTAND THE PERFORMANCE TRADEOFFS YOU’RE MAKING • BE AWARE OF MEMORY USAGE • BE AWARE OF GARBAGE COLLECTION K E Y TA K E AWAY S
63. SSL Sadness
64. M . B O X R C 1 . 2 488MS (20X CONCURRENCY)
65. W E R E A L I Z E D W E H A D N ’ T B E E N C O M P L E T E LY H O N E S T API IN PRODUCTION? OVER HTTPS API IN TESTS? OVER HTTP NOT A FAIR TEST
66. M . B O X R C 1 . 2 / W S S L 607MS (20X CONCURRENCY) PREVIOUSLY 488MS 24.4% SLOW DOWN
67. M . B O X R C 1 . 2 / W S S L 935MS (30X CONCURRENCY) PREVIOUSLY 595MS 57.1% SLOW DOWN
68. SSL
69. S S L KEYGEN IS MOSTLY COMPUTATIONAL BLOCKING COMPOUNDING SADNESS
70. S S L C I P H E R S DEFAULTS TO USE DIFFIE-HELLMAN DH IS EXPENSIVE NEED TO INVESTIGATE OTHER CIPHER SUITES, SECURITY TRADEOFFS, ETC.
71. S S L C I P H E R S & C O N N E C T I O N P O O L I N G SLOWDOWN TOO DRAMATIC? SOMETHING COULD BE BLOCKING POOLING NODE V0.12: “PROPER KEEPALIVE SUPPORT”
72. S S L C I P H E R S IN A PERFECT WORLD, NO SSL TALK TO A PRIVATE API HTTPS WOULD BE UNNECESSARY
73. • ALWAYS BE TRUE TO YOUR LIVE ENV. • UNDERSTAND YOUR TECH • SSL = COMPUTATION = HARD ON NODE • PERFORMANCE IS ALL ABOUT TRADEOFFS K E Y TA K E AWAY S
74. to infinity…
75. S T R E S S T E S T I N G INCREASE TRAFFIC, CONCURRENCY WILL THE SERVERS STAND UP?
76. 0" 5" 10" 15" 20" 25" 30" 35" 40" 45" 50" 30" 80" 130" 180" 230" 280" 330" 380" 430" 480" 30    32.82   40    35.60   50    37.33   100  42.90   200  44.35   500  43.88 C O N C U R R E N C Y V S . C O M P L E T E D R E Q U E S T S P E R S E C O N D
77. V S . C O M P L E T E D R E Q U E S T S P E R S E C O N D 10" 15" 20" 25" 30" 35" 40" 45" 50" 2   0   3   0   5   8 APPROACHING MAXIMUM EFFICIENCY
78. S T R E S S T E S T I N G 100% EFFICIENCY AT ~200X PLATEAUED AT ~44 RPS DIDN’T FALL OVER, EVEN AT 500X HANDLED ALL REQUESTS SUCCESSFULLY
79. • DIDN’T FALL OVER!!! • 100% EFFICIENCY ISN’T FAST OR DESIRED • IN PRODUCTION, KEEP A BUFFER K E Y TA K E AWAY S
80. @FREDKSCHOTT