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

Measuring and Logging Everything in Real Time

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.

Bastian Hofmann

April 08, 2016
Tweet

More Decks by Bastian Hofmann

Other Decks in Programming

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/
    [email protected]

    View Slide