Measuring and Logging Everything in Real Time

Do you know what is happening in your web application right now, this second, how many requests, logins, exceptions you have, how many and what data your users are generating and what the click through rate of each of your registration step is? Or do you know exactly which exception with which stack trace caused the error your users are seeing? If not, this talk will show how you can easily measure and log everything that happens in your application with the help of open source tools, such as Graphite, StatsD, Elasticsearch and Logstash, without influencing your production environment.

Transcript

1. Measuring &
   Logging
   Everything
   in Real-Time
   @BastianHofmann
   

   View Slide

2. Logging
   

   View Slide

3. Measuring
   

   View Slide

4. Real-Time
   

   View Slide

5. Many roads
   

   View Slide

6. A few words
   about me
   

   View Slide

7. View Slide

8. View Slide

9. View Slide

10. Questions? Ask
    

    View Slide

11. http://speakerdeck.com/u/bastianhofmann
    

    View Slide

12. Logging
    

    View Slide

13. For when
    something goes
    wrong
    

    View Slide

14. server
    error log
    access log
    debug logs
    slow query log
    ...
    

    View Slide

15. $ ssh my_simple_server
    

    View Slide

16. $ tail -f error.log
    $ cat error.log | grep Exception
    

    View Slide

17. Error Logs
    

    View Slide

18. ErrorLog /var/logs/apache/error.log
    

    View Slide

19. bool error_log ( string $message [, int
    $message_type = 0 [, string $destination [, string
    $extra_headers ]]] )
    

    View Slide

20. View Slide

21. callable set_exception_handler(
    callable $exception_handler
    );
    

    View Slide

22. Log additional info
    

    View Slide

23. View Slide

24. Not only error
    codes
    

    View Slide

25. Request
    Information
    

    View Slide

26. Handling Notices,
    Warnings, Errors
    

    View Slide

27. callable set_error_handler(
    callable $error_handler
    [, int $error_types = E_ALL |
    E_STRICT ]
    );
    

    View Slide

28. set_error_handler(
    function($errno, $msg, $file, $line) {
    $e = new \Exception();
    $error = [
    'type' => $errno,
    'message' => $msg,
    'file' => $file,
    'line' => $line,
    'trace' => $e->getTrace(),
    ];
    error_log(json_encode($error));
    return true;
    });
    

    View Slide

29. Or directly turn
    them into
    Exceptions
    

    View Slide

30. set_error_handler(
    function($errno, $msg, $file, $line) {
    switch ($errno) {
    case E_RECOVERABLE_ERROR:
    case E_USER_ERROR:
    throw new \ErrorException($msg, null, $errno, $file, $line);
    case E_WARNING:
    case E_USER_WARNING:
    case E_CORE_WARNING:
    case E_COMPILE_WARNING:
    throw new WarningException($msg, null, $errno, $file, $line);
    case E_NOTICE:
    case E_USER_NOTICE:
    throw new NoticeException($msg, null, $errno, $file, $line);
    case E_STRICT:
    throw new StrictException($msg, null, $errno, $file, $line);
    }
    return true;
    });
    $a = [];
    try {
    $b = $a['doesNotExist'];
    } catch (NoticeException $e) {
    }
    

    View Slide

31. But what about
    fatal errors
    

    View Slide

32. Use error_get_last()
    in a Shutdown
    Handler
    http://php.net/manual/en/function.error-
    get-last.php
    

    View Slide

33. View Slide

34. http://php.net/manual/en/class.error.php
    

    View Slide

35. Access Logs
    

    View Slide

36. 192.168.56.1 - - [09/Jul/2012:19:18:19
    +0200] "GET /rg_trunk/webroot/c/af10c/
    images/template/rg_logo_default.png HTTP/
    1.1" 200 882 "http://devm/rg_trunk/webroot/
    directory/publications/"
    

    View Slide

37. LogFormat "%h %l %u %t \"%r\" %>s %b" custom
    CustomLog /var/logs/apache/access.log custom
    http://httpd.apache.org/docs/2.2/mod/
    mod_log_config.html#logformat
    

    View Slide

38. http://de.php.net/apache_note
    string apache_note (
    string $note_name
    [, string $note_value = "" ]
    )
    

    View Slide

39. LogFormat "...\"%{referer}i\" \"%{user-
    agent}i\" %{session_id}n %{account_id}n..."
    custom
    

    View Slide

40. Debug Logs
    

    View Slide

41. https://github.com/Seldaek/monolog/
    

    View Slide

42. use Monolog\Logger;
    use Monolog\Handler\StreamHandler;
    // create a log channel
    $log = new Logger('name');
    $log->pushHandler(
    new StreamHandler(
    'path/to/your.log', Logger::WARNING
    )
    );
    // add records to the log
    $log->addWarning('Foo');
    $log->addError('Bar');
    

    View Slide

43. Handlers
    •Stream
    •Mail
    •FirePHP
    •ChromePHP
    •Socket
    •Roating File
    •MongoDB
    •Syslog
    •Gelf
    •Null
    •Test
    •FingersCrossed
    

    View Slide

44. Log in a structured
    way
    

    View Slide

45. JSON
    http://www.ietf.org/rfc/rfc4627.txt
    

    View Slide

46. use Monolog\Logger;
    use Monolog\Handler\StreamHandler;
    use Monolog\Formatter\JsonFormatter;
    $log = new Logger('name');
    $handler = new StreamHandler(
    'path/to/your.log', Logger::WARNING
    );
    $handler->setFormatter(new JsonFormatter());
    $log->pushHandler($handler);
    

    View Slide

47. Logs from other
    services
    

    View Slide

48. web server http service
    http service
    http service
    http service
    user request
    log
    log
    log
    log
    log
    

    View Slide

49. Correlation /
    Tracing ID
    

    View Slide

50. web server http service
    http service
    http service
    http service
    create
    unique
    trace_id for
    request
    user request
    trace_id
    trace_id
    trace_id
    trace_id
    log
    log
    log
    log
    log
    

    View Slide

51. X-Trace-Id: bbr8ehb984tbab894
    

    View Slide

52. web server http service
    http service
    http service
    http service
    create
    unique
    trace_id for
    request
    user request
    trace_id
    trace_id
    trace_id
    trace_id
    log
    log
    log
    log
    log
    

    View Slide

53. View Slide

54. View Slide

55. View Slide

56. Aggregate the logs
    in a central place
    

    View Slide

57. Make them easily
    full-text searchable
    

    View Slide

58. Make them
    aggregate-able
    

    View Slide

59. Always Log to file
    

    View Slide

60. Directly to a
    database
    

    View Slide

61. webserver webserver webserver
    DB
    

    View Slide

62. Disadvantages
    

    View Slide

63. Database is down?
    

    View Slide

64. Database is slow?
    

    View Slide

65. Database is full?
    

    View Slide

66. How to integrate
    access logs?
    

    View Slide

67. Influences
    application
    performance
    

    View Slide

68. Frontend?
    

    View Slide

69. Better solutions?
    

    View Slide

70. Logstash +
    Elasticsearch +
    Kibana
    

    View Slide

71. Full text search
    

    View Slide

72. Structured
    Messages
    

    View Slide

73. Always Log to file
    

    View Slide

74. Logstash
    elasticsearch
    webserver webserver webserver
    AMQP
    log log log
    logstash logstash logstash
    

    View Slide

75. logstash
    http://logstash.net/
    

    View Slide

76. input filter output
    

    View Slide

77. Very rich plugin
    system
    

    View Slide

78. Logstash
    elasticsearch
    webserver webserver webserver
    AMQP
    log log log
    logstash logstash logstash
    

    View Slide

79. input {
    file {
    type => "error"
    path =>
    [ "/var/logs/php/*.log" ]
    add_field =>
    [ "severity", "error" ]
    }
    file {
    type => "access"
    path =>
    [ "/var/logs/apache/*_access.log" ]
    add_field =>
    [ "severity", "info" ]
    }
    

    View Slide

80. filter{
    grok {
    match => ["@source",
    "\/%{USERNAME:facility}\.log$"]
    }
    grok {
    type => "access"
    pattern => "^%{IP:OriginalIp}
    \s[a-zA-Z0-9_-]+\s[a-zA-Z0-9_-]+\s\[.*?
    \]\s\"%{DATA:Request}..."
    }
    }
    

    View Slide

81. output {
    amqp {
    host => "amqp.host"
    exchange_type => "fanout"
    name => "logs"
    }
    }
    

    View Slide

82. Logstash
    elasticsearch
    webserver webserver webserver
    AMQP
    log log log
    logstash logstash logstash
    

    View Slide

83. input {

    rabbitmq {

    queue => "logs"

    host => "amqp.host"

    exchange => "ls_exchange"

    exclusive => false

    }

    }
    

    View Slide

84. filter {
    grok {

    match => [

    'Type','EntityNotFoundException|
    TimeoutException'

    ]

    break_on_match => true

    add_tag => ['not_serious']

    tag_on_failure => ['serious']

    }
    }
    

    View Slide

85. output {

    elasticsearch {

    embedded => false

    bind_host => "localhost"

    bind_port => "9305"

    host => "localhost"

    cluster => "logs"

    }

    }
    

    View Slide

86. Kibana
    http://www.elasticsearch.org/overview/kibana/
    

    View Slide

87. View Slide

88. Measuring
    

    View Slide

89. For knowing what
    happens
    

    View Slide

90. https://metrics.librato.com/
    

    View Slide

91. View Slide

92. Graphite
    http://graphite.wikidot.com/
    

    View Slide

93. View Slide

94. webserver webserver webserver
    graphite
    TCP
    

    View Slide

95. StatsD
    https://github.com/etsy/statsd/
    

    View Slide

96. webserver webserver webserver
    graphite
    UDP statsd
    TCP
    

    View Slide

97. webserver webserver webserver
    statsd statsd
    statsd
    graphite
    

    View Slide

98. webserver webserver webserver
    statsd statsd
    statsd
    graphite
    statsd
    

    View Slide

99. Metric?
    

    View Slide

100. Counters
     

     View Slide

101. Timers
     

     View Slide

102. Gauges
     

     View Slide

103. Anomaly detection
     

     View Slide

104. http://codeascraft.com/2013/06/11/introducing-kale/
     

     View Slide

105. What can we
     measure?
     

     View Slide

106. Business Metrics
     

     View Slide

107. Experiments (A/B Testing)
     

     View Slide

108. Partial rollouts
     

     View Slide

109. Technical Metrics
     

     View Slide

110. Response Times
     

     View Slide

111. Easiest approach:
     Get it out of the
     access log
     

     View Slide

112. 192.168.56.1 - - [09/Jul/2012:19:18:19
     +0200] "GET /rg_trunk/webroot/c/af10c/
     images/template/rg_logo_default.png HTTP/
     1.1" 200 882 "http://devm/rg_trunk/webroot/
     directory/publications/"
     

     View Slide

113. Or measure it in
     your PHP process
     

     View Slide

114. Is this actually what
     we want to
     measure?
     

     View Slide

115. External Resources
     CSS
     JavaScript
     Images
     Slow connections
     Slow
     Browsers
     SSL Handshakes
     DNS resolving
     

     View Slide

116. http://www.stevesouders.com/blog/2012/02/10/the-performance-golden-rule/
     

     View Slide

117. That is what we
     want to measure!
     

     View Slide

118. Navigation Timing
     API
     https://developer.mozilla.org/en-US/docs/
     Navigation_timing
     

     View Slide

119. View Slide

120. Resource Timing API
     http://www.w3.org/TR/resource-timing/
     

     View Slide

121. View Slide

122. https://github.com/lognormal/boomerang
     

     View Slide

123. Getting it back to
     the server
     

     View Slide

124. Tracking request
     

     View Slide

125. https://tracking.example.com/?
     page=profile&backend=123&co
     mplete=890&domReady=580
     

     View Slide

126. browser
     JS: boomerang
     logstash
     trackingServer
     access log
     requests
     tracking image
     with timing
     information as
     query
     parameters
     graphite
     statsd
     

     View Slide

127. Can we measure
     more?
     

     View Slide

128. Load balancer
     

     View Slide

129. Slow query logs
     

     View Slide

130. From within your
     PHP app
     

     View Slide

131. browser
     JS: boomerang
     logstash
     trackingServer
     access log
     requests
     tracking image
     with timing
     information as
     query
     parameters
     graphite
     statsd
     logstash
     load balancer
     access log
     logstash
     service
     access log
     

     View Slide

132. Database Queries
     

     View Slide

133. HTTP calls
     

     View Slide

134. Cache access
     

     View Slide

135. Rendering time
     

     View Slide

136. More fine grained
     metrics
     

     View Slide

137. By pages
     

     View Slide

138. By component
     

     View Slide

139. By browser
     

     View Slide

140. By country
     

     View Slide

141. Logged in / out
     

     View Slide

142. Profiling information
     

     View Slide

143. XHProf
     https://github.com/facebook/xhprof
     

     View Slide

144. Use it in production
     for a subset of
     requests
     

     View Slide

145. XHGUI
     https://github.com/perftools/xhgui
     

     View Slide

146. View Slide

147. View Slide

148. View Slide

149. View Slide

150. https://blackfire.io/
     

     View Slide

151. https://tidyways.io/
     

     View Slide

152. View Slide

153. View Slide

154. Symfony Debug
     Toolbar
     

     View Slide

155. View Slide

156. View Slide

157. Extend it
     http://symfony.com/doc/current/cookbook/profiler/
     data_collector.html
     

     View Slide

158. View Slide

159. View Slide

160. View Slide

161. View Slide

162. View Slide

163. View Slide

164. Aggregate it
     

     View Slide

165. View Slide

166. https://joind.in/talk/43978
     

     View Slide

167. http://twitter.com/BastianHofmann
     http://profiles.google.com/bashofmann
     http://lanyrd.com/people/BastianHofmann
     http://speakerdeck.com/u/bastianhofmann
     https://github.com/bashofmann
     https://www.researchgate.net/profile/Bastian_Hofmann/
     mail@bastianhofmann.de
     

     View Slide