{"action":"created","issue":{"url":"https://api.github.com/repos/elastic/logstash/issues/5733","repository_url":"https://api.github.com/repos/elastic/logstash","labels_url":"https://api.github.com/repos/elastic/logstash/issues/5733/labels{/name}","comments_url":"https://api.github.com/repos/elastic/logstash/issues/5733/comments","events_url":"https://api.github.com/repos/elastic/logstash/issues/5733/events","html_url":"https://github.com/elastic/logstash/issues/5733","id":169593192,"number":5733,"title":" The Logstash Slow log","user":{"login":"purbon","id":68540,"avatar_url":"https://avatars.githubusercontent.com/u/68540?v=3","gravatar_id":"","url":"https://api.github.com/users/purbon","html_url":"https://github.com/purbon","followers_url":"https://api.github.com/users/purbon/followers","following_url":"https://api.github.com/users/purbon/following{/other_user}","gists_url":"https://api.github.com/users/purbon/gists{/gist_id}","starred_url":"https://api.github.com/users/purbon/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/purbon/subscriptions","organizations_url":"https://api.github.com/users/purbon/orgs","repos_url":"https://api.github.com/users/purbon/repos","events_url":"https://api.github.com/users/purbon/events{/privacy}","received_events_url":"https://api.github.com/users/purbon/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/elastic/logstash/labels/design","name":"design","color":"eb6420"},{"url":"https://api.github.com/repos/elastic/logstash/labels/discuss","name":"discuss","color":"cc317c"},{"url":"https://api.github.com/repos/elastic/logstash/labels/Logging%20Improvements","name":"Logging Improvements","color":"bfd4f2"}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":19,"created_at":"2016-08-05T12:08:38Z","updated_at":"2016-08-10T14:24:50Z","closed_at":null,"body":"###  Description of the problem\r\n\r\nSystems like elasticsearch, mysql and other data processing engines have the concept of an slow log, a log file where the system is reporting slow operations. To have this in Logstash makes sense in order to increase the feedback users get.\r\n\r\n### The proposed system should be able to:\r\n\r\n* Be configurable. A user should be able to change a config variable to decide what means slow for a given component.\r\n* Should be integrated with all plugins flavors in Logstash, this means it should be possible to report slow operations from inputs, codecs, filters and outputs.\r\n* Should report also from core components, ex: pipeline being stalled. \r\n* Should be logged in a different file than the regular logs.\r\n* As much context as possible should be provided, this means:\r\n * The component (plugin, pipeline, etc..), the action, duration, event (if applicable), context (configuration?).\r\n* In the slow log there could be also context information useful to debug the problems.\r\n\r\n### Solution proposed\r\n\r\n> _Concrete details will be updated on demand as this idea gets developed, so take this proposal as an initial dump of ideas that will for sure evolve._\r\n\r\nTo implement this feature, specially if we just wanted to get slow_log mix with the current log, we could just reuse the logger instance, *however we aim for a more general structure*, this solution is discarded.\r\n\r\nWho should be initially reporting the slow operation?, definitely should be the component detecting the situation, we’ll use the grok filter as example to describe the solution. For the grok filter it should be transparent to report an slow operation, to report an slow operation should be as simple as:\r\n\r\n```report_slow_operation(action, duration, event, context, ….) ```\r\n\r\nBut internally in logstash this another situation, the log might need to get populated with collateral information such as current pipeline situation, workers and plugin status, etc This information should be gathered by other components inside the LS core logic, so this kind of mandates a system that is living in core and able to compose all necessary messages into a proper logger output.\r\n\r\nThe proposed solution will be:\r\n\r\n* A component that it stays inside logstash-core.\r\n* Is available to plugins, but also to core components.\r\n* Knows how to receive a message from one of this components and act accordingly.\r\n* Is able to gather contextual information when necessary.\r\n\r\nMore details could be grasp from an initial proof of concept:  \r\n_[Include PoC link when available]_.\r\n \r\n### Pros and Cons\r\n\r\n* Easier to grab extended context from the logstash agent and pipelines. Providing easier to debug logs for end users.\r\n* Easy interface with for the component consumers.\r\n* Properly single responsibility, providing us with easier to test and maintain components.\r\n* More complex to implementation than the straightforward solution.\r\n* Need to scale properly to multiple producers of content (slow operations).\r\n\r\n### Work packages\r\n\r\nFor the initial version of this component we aim to:\r\n\r\n* Make the current file settings available for plugins.\r\n* Build an slow log service able to receive slow log messages, gather context (when choosen to) and output the final log.\r\n* Enable plugins to report slow log operations. First candidate should be grok filter.\r\n* Have good unit and integration tests for the feature.\r\n* Add an slow log feature flag (disabled by default)\r\n\r\nFeature work:\r\n* When the work on the new logging gets merged, would be nice to try to exploit the feature in there that enable users to change settings on demand from the api. Should be possible to:\r\n * Enable/Disable Slow-Log.\r\n * Change slow-log thresholds, for example what slow means for the grok filter.\r\n* Analyse if more components/operations could be added. Should they be added in different log files?\r\n* Analyse slow-query logs could be a difficult thing, especially if they grow a lot. To provide an easy debug experience, would be nice to provide ways to visualize this data.\r\n\r\n### What others are doing\r\n\r\n#### MySQL and related projects\r\n\r\nMySQL provide its users with slow query log consisting of SQL statements that took more than long_query_time seconds to execute and required at least min_examined_row_limit rows to be examined. Execution time is usually reported with microseconds resolution, unless the logs are send to table where the microsecond part is ignored.\r\nSome queries get not logged by default like administrative statements, replicated statement, etc.\r\n\r\nRef:  https://dev.mysql.com/doc/refman/5.6/en/slow-query-log.html\r\n\r\nSimilar approaches are taken by [Percona](https://www.percona.com/doc/percona-server/5.6/diagnostics/slow_extended.html) and [MariaDB](https://mariadb.com/kb/en/mariadb/slow-query-log-overview/).\r\n\r\nExample of Percona SlowLog\r\n\r\n```\r\n# Time: 130601  8:01:06.058915\r\n# User@Host: root[root] @ localhost []  Id:    42\r\n# Schema: imdb  Last_errno: 0  Killed: 0\r\n# Query_time: 7.725616  Lock_time: 0.000328  Rows_sent: 4  Rows_examined: 1543720  Rows_affected: 0\r\n# Bytes_sent: 272  Tmp_tables: 0  Tmp_disk_tables: 0  Tmp_table_sizes: 0\r\n# QC_Hit: No  Full_scan: Yes  Full_join: No  Tmp_table: No  Tmp_table_on_disk: No\r\n# Filesort: No  Filesort_on_disk: No  Merge_passes: 0\r\nSET timestamp=1370073666;\r\nSELECT id,title,production_year FROM title WHERE title = 'Bambi';\r\n```\r\n\r\n#### Elasticsearch\r\n\r\nElasticsearch have two types of low logs, one for searches and one for indexing, both works in similar fashion. The search slow log allows you to log slow search (query and fetch phases) into a dedicated log file.\r\nThresholds can be set for both the query phase of the execution, and fetch phase. They are then used when the loglevel is set to does as the limit to log.\r\n\r\nSearch slow log configuration example, [latest 2.3 branch]\r\n\r\n```\r\nindex.search.slowlog.threshold.query.warn: 10s\r\nindex.search.slowlog.threshold.query.info: 5s\r\nindex.search.slowlog.threshold.query.debug: 2s\r\nindex.search.slowlog.threshold.query.trace: 500ms\r\n```\r\n\r\nBoth logs log to a dedicated file, one for slow queries and one for indexing.\r\n\r\nIs specific for the indexing log that the user get the option to log part of the _source field, how much is logged can be configured (default is first 1000 characters).\r\n\r\nRef: https://www.elastic.co/guide/en/elasticsearch/reference/current/index-modules-slowlog.html\r\n\r\n\r\nHappy to discuss details."},"comment":{"url":"https://api.github.com/repos/elastic/logstash/issues/comments/238882890","html_url":"https://github.com/elastic/logstash/issues/5733#issuecomment-238882890","issue_url":"https://api.github.com/repos/elastic/logstash/issues/5733","id":238882890,"user":{"login":"guyboertje","id":84912,"avatar_url":"https://avatars.githubusercontent.com/u/84912?v=3","gravatar_id":"","url":"https://api.github.com/users/guyboertje","html_url":"https://github.com/guyboertje","followers_url":"https://api.github.com/users/guyboertje/followers","following_url":"https://api.github.com/users/guyboertje/following{/other_user}","gists_url":"https://api.github.com/users/guyboertje/gists{/gist_id}","starred_url":"https://api.github.com/users/guyboertje/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/guyboertje/subscriptions","organizations_url":"https://api.github.com/users/guyboertje/orgs","repos_url":"https://api.github.com/users/guyboertje/repos","events_url":"https://api.github.com/users/guyboertje/events{/privacy}","received_events_url":"https://api.github.com/users/guyboertje/received_events","type":"User","site_admin":false},"created_at":"2016-08-10T14:24:50Z","updated_at":"2016-08-10T14:24:50Z","body":"@ph and @purbon - all good points.\r\n\r\nIt would be sad to have to add two statements, 1 for logging the slow activity and 2 for the metric.\r\nI mean the metric object would have to have all the data/content to create a top N type entry anyway - could it not log as well?"}}
{"actor":{"display_login":"guyboertje"}}