{"action":"created","issue":{"url":"https://api.github.com/repos/elastic/logstash/issues/11105","repository_url":"https://api.github.com/repos/elastic/logstash","labels_url":"https://api.github.com/repos/elastic/logstash/issues/11105/labels{/name}","comments_url":"https://api.github.com/repos/elastic/logstash/issues/11105/comments","events_url":"https://api.github.com/repos/elastic/logstash/issues/11105/events","html_url":"https://github.com/elastic/logstash/issues/11105","id":487766605,"node_id":"MDU6SXNzdWU0ODc3NjY2MDU=","number":11105,"title":"Start time much longer after upgrade from 6.x to 7.x","user":{"login":"peacand","id":1843038,"node_id":"MDQ6VXNlcjE4NDMwMzg=","avatar_url":"https://avatars3.githubusercontent.com/u/1843038?v=4","gravatar_id":"","url":"https://api.github.com/users/peacand","html_url":"https://github.com/peacand","followers_url":"https://api.github.com/users/peacand/followers","following_url":"https://api.github.com/users/peacand/following{/other_user}","gists_url":"https://api.github.com/users/peacand/gists{/gist_id}","starred_url":"https://api.github.com/users/peacand/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/peacand/subscriptions","organizations_url":"https://api.github.com/users/peacand/orgs","repos_url":"https://api.github.com/users/peacand/repos","events_url":"https://api.github.com/users/peacand/events{/privacy}","received_events_url":"https://api.github.com/users/peacand/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":10,"created_at":"2019-08-31T12:44:01Z","updated_at":"2019-12-20T22:34:48Z","closed_at":null,"author_association":"NONE","body":"Hi,\r\n\r\nI've upgraded my Logstash instances from 6.8 to 7.3. After the upgrade, I've noticed a startup time ~3x higher, going from ~3min to ~9min. I'm surprised because I red in the release notes that the startup time is expected to be much faster with the new Java engine.\r\n\r\nTo give you more details about what I observe, the startup behavior is actually different from 6 to 7.\r\n\r\nIn version 6, during startup, in the logs, I had nothing for ~3min and then in a few seconds, I had all these lines and Logstash was 100% ready and processing logs :\r\n\r\n```\r\nStarting UDP listener {:address=>\"0.0.0.0:xxxxx\"}\r\nUDP listener started {:address=>\"0.0.0.0:xxxxx\", :receive_buffer_bytes=>\"106496\", :queue_size=>\"2000\"}\r\nStarting UDP listener {:address=>\"0.0.0.0:yyyyy\"}\r\nUDP listener started {:address=>\"0.0.0.0:yyyyy\", :receive_buffer_bytes=>\"106496\", :queue_size=>\"2000\"}\r\n....\r\nPipelines running {:count=>1, :running_pipelines=>[:main], :non_running_pipelines=>[]}\r\nOpening file {:path=>\"/var/log/xxxxxx\"}\r\n....\r\n```\r\n\r\nBut in version 7 it's different. In ~1min after the startup command, I get these logs :\r\n\r\n```\r\nStarting UDP listener {:address=>\"0.0.0.0:xxxxx\"}\r\nUDP listener started {:address=>\"0.0.0.0:xxxxx\", :receive_buffer_bytes=>\"106496\", :queue_size=>\"2000\"}\r\nStarting UDP listener {:address=>\"0.0.0.0:yyyyy\"}\r\nUDP listener started {:address=>\"0.0.0.0:yyyyy\", :receive_buffer_bytes=>\"106496\", :queue_size=>\"2000\"}\r\n....\r\nPipelines running {:count=>1, :running_pipelines=>[:main], :non_running_pipelines=>[]}\r\n```\r\n\r\nSo at that time it looks like the pipeline is ready. But in fact not. There is no output at that time. The output starts coming ~8 minutes later. And during this time where the inputs are ready, the pipeline is supposed to run but there is no output. I've strace the process and it's actually generating all the Java CompileDataset in /tmp. In my case there are 400 files like that to generate. After the last file is generated, the output starts coming.\r\n\r\nSo it looks like the pipeline is ready in ~1min, but in fact it takes really 9min.\r\n\r\nDo you know why it takes so long ? Did I miss a configuration option while upgrading to 7.x ?\r\nIn my pipeline I use many custom Ruby filters, both inline and using external Ruby script files.\r\nCould it explain this high Java generation time ?\r\n\r\nThank you for your help\r\n"},"comment":{"url":"https://api.github.com/repos/elastic/logstash/issues/comments/568112618","html_url":"https://github.com/elastic/logstash/issues/11105#issuecomment-568112618","issue_url":"https://api.github.com/repos/elastic/logstash/issues/11105","id":568112618,"node_id":"MDEyOklzc3VlQ29tbWVudDU2ODExMjYxOA==","user":{"login":"colinsurprenant","id":2010,"node_id":"MDQ6VXNlcjIwMTA=","avatar_url":"https://avatars1.githubusercontent.com/u/2010?v=4","gravatar_id":"","url":"https://api.github.com/users/colinsurprenant","html_url":"https://github.com/colinsurprenant","followers_url":"https://api.github.com/users/colinsurprenant/followers","following_url":"https://api.github.com/users/colinsurprenant/following{/other_user}","gists_url":"https://api.github.com/users/colinsurprenant/gists{/gist_id}","starred_url":"https://api.github.com/users/colinsurprenant/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/colinsurprenant/subscriptions","organizations_url":"https://api.github.com/users/colinsurprenant/orgs","repos_url":"https://api.github.com/users/colinsurprenant/repos","events_url":"https://api.github.com/users/colinsurprenant/events{/privacy}","received_events_url":"https://api.github.com/users/colinsurprenant/received_events","type":"User","site_admin":false},"created_at":"2019-12-20T22:34:48Z","updated_at":"2019-12-20T22:34:48Z","author_association":"CONTRIBUTOR","body":"I have spent some time investigating this problem and was able to replicate quite easily using a very simple config with a large (50x) repetition of an `if` statement in the `filter {}` section.\r\n\r\nThe compilation of a pipeline is a substantial operation which is relative to the total size of the pipeline definition. Substantially optimizing this part is unlikely in the near future but this is not really the problem here.\r\n\r\n### The problem\r\n\r\nA single `CompiledPipeline` is created per pipeline definition:\r\n\r\nhttps://github.com/elastic/logstash/blob/5fd5fb2db2ce45a8da3d52f75ceef1b4caa7cdfb/logstash-core/src/main/java/org/logstash/execution/JavaBasePipelineExt.java#L48\r\n\r\nbut a `CompileExecution` is actually repeated **per worker** :\r\n\r\nhttps://github.com/elastic/logstash/blob/5fd5fb2db2ce45a8da3d52f75ceef1b4caa7cdfb/logstash-core/src/main/java/org/logstash/config/ir/CompiledPipeline.java#L116-L123\r\n\r\nhttps://github.com/elastic/logstash/blob/5fd5fb2db2ce45a8da3d52f75ceef1b4caa7cdfb/logstash-core/src/main/java/org/logstash/execution/WorkerLoop.java#L46\r\n\r\n### Solution\r\n\r\nIt seems that if we could avoid creating a new `CompiledPipeline` per worker it would solve the problem by having a single actual compilation. Currently separate `CompiledPipeline` are required per worker because they hold per worker state. I have still to better understand that part. \r\n\r\nI tried to see if a trivial shallow cloning of the `CompiledPipeline` per worker would work and while it does significantly reduce the startup time, many java_pipeline specs are failing. (For example a test pipeline on a single worker would take 20s to start and with 128 workers it would take 2m30s but with my shallow clone patch with 128 workers it would take approximately the same time as a single worker, which makes sense). \r\n\r\nI will continue investigating this to see if/how we could avoid this large per worker compilation cost. \r\n\r\n\r\n"}}
{"actor":{"display_login":"colinsurprenant"}}