Parsing the php-fpm slowlog
ActivePublic
Actions

Authored by Joe on Oct 25 2021, 9:20 AM.

Tags

None

Referenced Files

	F34709963: Parsing the php-fpm slowlog
	Oct 25 2021, 9:21 AM

	F34709958: Parsing the php-fpm slowlog
	Oct 25 2021, 9:20 AM

Subscribers

colewhite

	{
	"stacktrace": [
	{
	"line": "241",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/includes/parser/PPNode_Hash_Tree.php",
	"function": "__construct()",
	"address": "0x00007f3cb2222f60"
	},
	{
	"line": "219",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/includes/parser/PPNode_Hash_Tree.php",
	"function": "splitRawArg()",
	"address": "0x00007f3cb2222e90"
	},
	{
	"line": "211",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/extensions/ParserFunctions/includes/ParserFunctions.php",
	"function": "splitArg()",
	"address": "0x00007f3cb2222e30"
	},
	{
	"line": "3398",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/includes/parser/Parser.php",
	"function": "switch()",
	"address": "0x00007f3cb2222c80"
	},
	{
	"line": "3081",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/includes/parser/Parser.php",
	"function": "callParserFunction()",
	"address": "0x00007f3cb2222b30"
	},
	{
	"line": "276",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/includes/parser/PPFrame_Hash.php",
	"function": "braceSubstitution()",
	"address": "0x00007f3cb2222810"
	},
	{
	"line": "227",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/extensions/ParserFunctions/includes/ParserFunctions.php",
	"function": "expand()",
	"address": "0x00007f3cb2222630"
	},
	{
	"line": "3398",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/includes/parser/Parser.php",
	"function": "switch()",
	"address": "0x00007f3cb2222420"
	},
	{
	"line": "3081",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/includes/parser/Parser.php",
	"function": "callParserFunction()",
	"address": "0x00007f3cb22222d0"
	},
	{
	"line": "276",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/includes/parser/PPFrame_Hash.php",
	"function": "braceSubstitution()",
	"address": "0x00007f3cb2221fb0"
	},
	{
	"line": "3272",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/includes/parser/Parser.php",
	"function": "expand()",
	"address": "0x00007f3cb2221dd0"
	},
	{
	"line": "276",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/includes/parser/PPFrame_Hash.php",
	"function": "braceSubstitution()",
	"address": "0x00007f3cb2221ab0"
	},
	{
	"line": "146",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/extensions/ParserFunctions/includes/ParserFunctions.php",
	"function": "expand()",
	"address": "0x00007f3cb22218d0"
	},
	{
	"line": "3398",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/includes/parser/Parser.php",
	"function": "ifeq()",
	"address": "0x00007f3cb2221780"
	},
	{
	"line": "3081",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/includes/parser/Parser.php",
	"function": "callParserFunction()",
	"address": "0x00007f3cb2221630"
	},
	{
	"line": "276",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/includes/parser/PPFrame_Hash.php",
	"function": "braceSubstitution()",
	"address": "0x00007f3cb2221310"
	},
	{
	"line": "3272",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/includes/parser/Parser.php",
	"function": "expand()",
	"address": "0x00007f3cb2221130"
	},
	{
	"line": "276",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/includes/parser/PPFrame_Hash.php",
	"function": "braceSubstitution()",
	"address": "0x00007f3cb2220e10"
	},
	{
	"line": "178",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/includes/parser/PPTemplateFrame_Hash.php",
	"function": "expand()",
	"address": "0x00007f3cb2220c30"
	},
	{
	"line": "190",
	"file": "/srv/mediawiki/php-1.38.0-wmf.5/includes/parser/PPTemplateFrame_Hash.php",
	"function": "getNamedArgument()",
	"address": "0x00007f3cb2220b50"
	}
	],
	"script_filename": "/srv/mediawiki/docroot/wikipedia.org/w/index.php",
	"pid": "22842",
	"pool": " www",
	"date": "22-Oct-2021 00:01:00"
	}

Event Timeline

Joe created this paste.Oct 25 2021, 9:20 AM

Joe updated the paste's language from autodetect to json.

Joe edited the content of this paste. (Show Details)

This is the result of parsing a php-fpm slowlog trace. This is obtained as follows:

Read the input file with imfile's readMode set to 1, so that multiline messages are compacted for paragraphs
Apply the following normalizing rule

version=2
rule=:%[
    {"type": "literal", "text": "["},
    {"name": "date", "type": "char-to", "extradata": "]"},
    {"type": "literal", "text": "]  [pool"},
    {"name": "pool","type": "char-to", "extradata": "]"},
    {"type": "literal", "text": "] pid "},
    {"name": "pid", "type": "number"},
    {"type": "literal", "text": "#012"},
    {"type": "literal", "text": "script_filename = "},
    {"name": "script_filename", "type": "char-to", "extradata": "#"},
    {"type": "literal", "text": "#012"},
    {
        "name": "stacktrace",
        "type": "repeat",
        "while": {"type":"literal", "text":"#012"},
        "parser": [
            {"type": "literal", "text": "["},
            {"name": "address", "type": "char-to", "extradata": "]"},
            {"type": "literal", "text": "] "},
            {"name": "function", "type": "word"},
            {"type": "literal", "text": " "},
            {"name": "file", "type": "char-to", "extradata": ":"},
            {"type": "literal", "text": ":"},
            {"name": "line", "type": "number"}
        ]
    },
    {"type": "literal", "text": "#"}
    ]%

Open questions:

Can we improve date parsing?
Is it useful to get this to logstash? To the centralized syslog?
Is there a message size limitation I should be aware of?

Joe mentioned this in T288851: Make logging work for mediawiki in k8s.Oct 25 2021, 1:32 PM

In P17591#90163, @Joe wrote:

Can we improve date parsing?

ECS has built-in support for date parsing timestamp fields of varying formats.

Is it useful to get this to logstash? To the centralized syslog?

I would venture to guess yes if it is valuable to dashboard and/or generate metrics on this data.

Is there a message size limitation I should be aware of?

It was indicated that 1MB is well below the ES absolute maximum message size. If that's the case, it should be fine.

Parsing the php-fpm slowlogActivePublicActions

Event Timeline

Parsing the php-fpm slowlog
ActivePublic
Actions