{"thread":{"id":"48879","subject":"[PATCH v1 00/25] RFC: structured logging","startedAt":"2018-07-13T16:56:32Z","lastAt":"2018-08-28T18:47:18Z","messageCount":38,"participants":["git@jeffhostetler.com","David Lang","Simon Ruderich","Jeff Hostetler","SZEDER Gábor","Ben Peart","Jonathan Nieder","Junio C Hamano"],"isPatch":true,"patchVersion":1,"patchTotal":25},"messages":[{"id":"352480","messageId":"20180713165621.52017-1-git@jeffhostetler.com","threadId":"48879","inReplyTo":null,"subject":"[PATCH v1 00/25] RFC: structured logging","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:55:56Z","receivedAt":"2018-07-13T16:56:32Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nThis RFC patch series adds structured logging to git. The motivation,\nbackground, and limitations of this feature are described at the\nbeginning of the design document in the first commit. The design\ndocument also contains a section comparing this feature with the\nexisting GIT_TRACE feature. So I won't go into great detail here in\nthe cover letter.\n\nMy primary focus in this RFC is to reach agreement on the structured\nlogging facility. This includes the basic approach and the various\nlogging fields and timers.\n\nThis patch series also includes several example usage commits, such as\nadding timers around do_{read,write}_index, that demonstrate the\ncapabilities of the structured logging facility. I only added a few\nexamples for things that I think we'll want long-term. I did not\nattempt to instrument everything.\n\nThis patch series requires V11 of my json-writer patch series.\n\n\nJeff Hostetler (25):\n structured-logging: design document\n structured-logging: add STRUCTURED_LOGGING=1 to Makefile\n structured-logging: add structured logging framework\n structured-logging: add session-id to log events\n structured-logging: set sub_command field for branch command\n structured-logging: set sub_command field for checkout command\n structured-logging: t0420 basic tests\n structured-logging: add detail-event facility\n structured-logging: add detail-event for lazy_init_name_hash\n structured-logging: add timer facility\n structured-logging: add timer around do_read_index\n structured-logging: add timer around do_write_index\n structured-logging: add timer around wt-status functions\n structured-logging: add timer around preload_index\n structured-logging: t0420 tests for timers\n structured-logging: add aux-data facility\n structured-logging: add aux-data for index size\n structured-logging: add aux-data for size of sparse-checkout file\n structured-logging: t0420 tests for aux-data\n structured-logging: add structured logging to remote-curl\n structured-logging: add detail-events for child processes\n structured-logging: add child process classification\n structured-logging: t0420 tests for child process detail events\n structured-logging: t0420 tests for interacitve child_summary\n structured-logging: add config data facility\n\n Documentation/config.txt | 33 +\n Documentation/git.txt | 6 +\n Documentation/technical/structured-logging.txt | 816 ++++++++++++++++\n Makefile | 8 +\n builtin/branch.c | 8 +\n builtin/checkout.c | 7 +\n compat/mingw.h | 7 +\n config.c | 3 +\n editor.c | 1 +\n git-compat-util.h | 9 +\n git.c | 10 +-\n name-hash.c | 26 +\n pager.c | 1 +\n preload-index.c | 6 +\n read-cache.c | 14 +\n remote-curl.c | 16 +-\n run-command.c | 14 +-\n run-command.h | 2 +\n structured-logging.c | 1219 ++++++++++++++++++++++++\n structured-logging.h | 179 ++++\n sub-process.c | 1 +\n t/t0001-init.sh | 1 +\n t/t0420-structured-logging.sh | 293 ++++++\n t/t0420/parse_json.perl | 52 +\n t/test-lib.sh | 1 +\n unpack-trees.c | 4 +-\n usage.c | 4 +\n wt-status.c | 20 +\n 28 files changed, 2757 insertions(+), 4 deletions(-)\n create mode 100644 Documentation/technical/structured-logging.txt\n create mode 100644 structured-logging.c\n create mode 100644 structured-logging.h\n create mode 100755 t/t0420-structured-logging.sh\n create mode 100644 t/t0420/parse_json.perl\n\n-- \n2.9.3\n\n"},{"id":"352481","messageId":"20180713165621.52017-2-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 01/25] structured-logging: design document","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:55:57Z","receivedAt":"2018-07-13T16:56:34Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nSigned-off-by: Jeff Hostetler \n---\n Documentation/technical/structured-logging.txt | 816 +++++++++++++++++++++++++\n 1 file changed, 816 insertions(+)\n create mode 100644 Documentation/technical/structured-logging.txt\n\ndiff --git a/Documentation/technical/structured-logging.txt b/Documentation/technical/structured-logging.txt\nnew file mode 100644\nindex 0000000..794c614\n--- /dev/null\n+++ b/Documentation/technical/structured-logging.txt\n@@ -0,0 +1,816 @@\n+Structured Logging\n+==================\n+\n+Structured Logging (SLOG) is an optional feature to allow Git to\n+generate structured log data for executed commands. This includes\n+command line arguments, command run times, error codes and messages,\n+child process information, time spent in various critical functions,\n+and repository data-shape information. Data is written to a target\n+log file in JSON[1,2,3] format.\n+\n+SLOG is disabled by default. Several steps are required to enable it:\n+\n+1. Add the compile-time flag \"STRUCTURED_LOGGING=1\" when building git\n+ to include the SLOG routines in the git executable.\n+\n+2. Set \"slog.*\" config settings[5] to enable SLOG in your repo.\n+\n+\n+Motivation\n+==========\n+\n+Git users may be faced with scenarios that are surprisingly slow or\n+produce unexpected results. And Git developers may have difficulty\n+reproducing these experiences. Structured logging allows users to\n+provide developers with additional usage, performance and error data\n+that can help diagnose and debug issues.\n+\n+Many Git hosting providers and users with many developers have bespoke\n+efforts to help troubleshoot problems; for example, command wrappers,\n+custom pre- and post-command hooks, and custom instrumentation of Git\n+code. These are inefficient and/or difficult to maintain. The goal\n+of SLOG is to provide this data as efficiently as possible.\n+\n+And having structured rather than free format log data, will help\n+developers with their analysis.\n+\n+\n+Background (Git Merge 2018 Barcelona)\n+=====================================\n+\n+Performance and/or error logging was discussed during the contributor's\n+summit in Barcelona. Here are the relevant notes from the meeting\n+minutes[6].\n+\n+> Performance misc (Ævar)\n+> -----------------------\n+> [...]\n+> - central error reporting for git\n+> - `git status` logging\n+> - git config that collects data, pushes to known endpoint with `git push`\n+> - pre_command and post_command hooks, for logs\n+> - `gvfs diagnose` that looks at packfiles, etc\n+> - detect BSODs, etc\n+> - Dropbox writes out json with index properties and command-line\n+> information for status/fetch/push, fork/execs external tool to upload\n+> - windows trace facility; would be nice to have cross-platform\n+> - would hosting providers care?\n+> - zipfile of logs to give when debugging\n+> - sanitizing data is harder\n+> - more in a company setting\n+> - fileshare to upload zipfile\n+> - most of the errors are proxy when they shouldn't, wrong proxy, proxy\n+> specific to particular URL; so upload endpoint wouldn't work\n+> - GIT_TRACE is supposed to be that (for proxy)\n+> - but we need more trace variables\n+> - series to make tracing cheaper\n+> - except that curl selects the proxy\n+> - trace should have an API, so it can call an executable\n+> - dump to .git/traces/... and everything else happens externally\n+> - tools like visual studio can't set GIT_TRACE, so\n+> - sourcetree has seen user environments where commands just take forever\n+> - third-party tools like perf/strace - could we be better leveraging those?\n+> - distribute turn-key solution to handout to collect more data?\n+\n+\n+A Quick Example\n+===============\n+\n+Note: JSON pretty-printing is enabled in all of the examples shown in\n+this document. When pretty-printing is turned off, each event is\n+written on a single line. Pretty-printing is intended for debugging.\n+It should be turned off in production to make post-processing easier.\n+\n+ $ git config slog.pretty \n+\n+Here is a quick example showing SLOG data for \"git status\". This\n+example has all optional features turned off. It contains 2 events.\n+The first is generated when the command started and the second when it\n+ended.\n+\n+{\n+ \"event\": \"cmd_start\",\n+ \"clock_us\": 1530273550667800,\n+ \"pid\": 107270,\n+ \"sid\": \"1530273550667800-107270\",\n+ \"command\": \"status\",\n+ \"argv\": [\n+ \"./git\",\n+ \"status\"\n+ ]\n+}\n+{\n+ \"event\": \"cmd_exit\",\n+ \"clock_us\": 1530273550680460,\n+ \"pid\": 107270,\n+ \"sid\": \"1530273550667800-107270\",\n+ \"command\": \"status\",\n+ \"argv\": [\n+ \"./git\",\n+ \"status\"\n+ ],\n+ \"result\": {\n+ \"exit_code\": 0,\n+ \"elapsed_core_us\": 12573,\n+ \"elapsed_total_us\": 12660\n+ },\n+ \"version\": {\n+ \"git\": \"2.18.0.rc0.83.gde7fb7c\",\n+ \"slog\": 0\n+ },\n+ \"config\": {\n+ \"slog\": {\n+ \"detail\": 0,\n+ \"timers\": 0,\n+ \"aux\": 0\n+ }\n+ }\n+}\n+\n+Both events fields describing the event name, the event time (in\n+microseconds since the epoch), the OS process-id, a unique session-id\n+(described later), the normalized command name, and a vector of the\n+original command line arguments.\n+\n+The \"cmd_exit\" event additionally contains information about how the\n+process exited, the elapsed time, the version of git and the SLOG\n+format, and important SLOG configuration settings.\n+\n+The fields in the \"cmd_start\" event are replicated in the \"cmd_exit\"\n+event. This allows log file post-processors to operate in 2 modes:\n+\n+1. Just look at the \"cmd_exit\" events. This us useful if you just\n+ want to analyze the command summary data.\n+\n+2. Look at the \"cmd_start\" and \"cmd_exit\" events as bracketing a time\n+ span and examine the detailed activity between. For example, SLOG\n+ can optionally generate \"detail\" events when spawning child\n+ processes and those processes may themselves generate \"cmd_start\"\n+ and \"cmd_exit\" events. The (top-level) \"cmd_start\" event serves as\n+ the starting bracket of all of that activity.\n+\n+\n+Target Log File\n+===============\n+\n+SLOG writes events to a log file. File logging works much like\n+GIT_TRACE where events are appended to a file on disk.\n+\n+Logging is enabled if the config variable \"slog.path\" is set to an\n+absolute pathname.\n+\n+As with GIT_TRACE, this file is local and private to the user's\n+system. Log file management and rotation is beyond the scope of the\n+SLOG effort.\n+\n+Similarly, if a user wants to provide this data to a developer, they\n+must explicitly make these log files available; SLOG does not\n+broadcast any of this information. It is up to the users of this\n+system to decide if any sensitive information should be sanitized, and\n+how to export the logs.\n+\n+\n+Comparison with GIT_TRACE\n+=========================\n+\n+SLOG is very similar to the existing GIT_TRACE[4] API because both\n+write event messages at various points during a command. However,\n+there are some fundamental differences that warrant it being\n+considered a separate feature rather than just another\n+GIT_TRACE_:\n+\n+1. GIT_TRACE events are unrelated, line-by-line logging. SLOG has\n+ line-by-line events that show command progress and can serve as\n+ structured debug messages. SLOG also supports accumulating summary\n+ data (such as timers) that are automatically added to the final\n+ `cmd_exit` event.\n+\n+2. GIT_TRACE events are unstructured free format printf-style messages\n+ which makes post-processing difficult. SLOG events are written in\n+ JSON and can be easily parsed using Perl, Python, and other tools.\n+\n+3. SLOG uses a well-defined API to build SLOG events containing\n+ well-defined fields to make post-command analysis easier.\n+\n+4. It should be easier to filter/redact sensitive information from\n+ SLOG data than from free form data.\n+\n+5. GIT_TRACE events are controlled by one or more global environment\n+ variables which makes it awkward to selectively log some repos and\n+ not others. SLOG events are controlled by a few configuration\n+ settings[5]. Users (or system administrators) can configure\n+ logging using repo-local or global config settings.\n+\n+6. GIT_TRACE events do not identify the git process. This makes it\n+ difficult to associate all of events from a particular command.\n+ Each SLOG event contains a session id to allow all events for a\n+ command to be identified.\n+\n+7. Some git commands spawn child git commands. GIT_TRACE has no\n+ mechanism to associate events from a child process with the parent\n+ process. SLOG session ids allow child/parent relationships to be\n+ tracked (even if there is an intermediate /bin/sh process between\n+ them).\n+\n+8. GIT_TRACE supports logging to a file or stderr. SLOG only logs to\n+ a file.\n+\n+9. Smashing SLOG into GIT_TRACE doesn't feel like a good fit. The 2\n+ APIs share nothing other than the concept that they write logging\n+ data.\n+\n+\n+[1] http://json.org/\n+[2] http://www.ietf.org/rfc/rfc7159.txt\n+[3] See UTF-8 limitations described in json-writer.h\n+[4] Documentation/technical/api-trace.txt\n+[5] See \"slog.*\" in Documentation/config.txt\n+[6] https://public-inbox.org/git/20180313004940.GG61720@google.com/t/\n+\n+\n+SLOG Format (V0)\n+================\n+\n+SLOG writes a series of events to the log target. Each event is a\n+self-describing JSON object.\n+\n+ LF\n+ LF\n+ LF\n+ ...\n+\n+Each event record in the log file is an independent and complete JSON\n+object. JSON parsers should process the file line-by-line rather than\n+trying to parse the entire file into a single object.\n+\n+ Note: It may be difficult for parsers to find record boundaries if\n+ pretty-printing is enabled, so it recommended that pretty-printing\n+ only be enabled for interactive debugging and analysis.\n+\n+Every contains the following fields (F1):\n+\n+ \"event\" : \n+ \"clock_us\" : \n+ \"pid\" : \n+ \"sid\" : \n+\n+ \"command\" : \n+ \"sub_command\" : (optional)\n+\n+ is one of \"cmd_start\", \"cmd_end\", or \"detail\".\n+\n+ is the time of the event in microseconds since the epoch.\n+\n+ is the process-id (from getpid()).\n+\n+ is a session-id. (Described later)\n+\n+ is a (possibly normalized) command name. This is\n+ usually taken from the cmd_struct[] table after git parses the\n+ command line and calls the appropriate cmd_() function.\n+ Having it in a top-level field saves post-processors from having\n+ to re-parse the command line to discover it.\n+\n+ further qualifies the command. This field is\n+ present for common commands that have multiple command modes. For\n+ example, checkout can either change branches and do a full\n+ checkout or it can checkout (refresh) an individual file. A\n+ post-processor wanting to compute percentiles for the time spent\n+ by branch-changing checkouts could easily filter out the\n+ individual file checkouts (and without having to re-parse the\n+ command line).\n+\n+ The set of sub_command values are command-specific and are not\n+ listed here.\n+\n+\"event\": \"cmd_start\"\n+-------------------\n+\n+The \"cmd_start\" event is emitted when git starts when cmd_main() is\n+called. In addition to the F1 fields, it contains the following\n+fields (F2):\n+\n+ \"argv\" : \n+\n+ is an array of the original command line arguments given to the\n+ command (before git.c has a chance to remove the global options\n+ before the verb.\n+\n+\n+\"event\": \"cmd_exit\"\n+-------------------\n+\n+The \"cmd_exit\" event is emitted immediately before git exits (during\n+an atexit() routine). It contains the F1 and F2 fields as described\n+above. It also contains the the following fields (F3):\n+\n+ \"result.exit_code\" : \n+ \"result.errors\" : (optional)\n+ \"result.elapsed_core_us\" : \n+ \"result.elapsed_total_us\" : \n+ \"result.signal\" : (optional)\n+\n+ \"verion.git\" : \n+ \"version.slog\" : \n+\n+ \"config.slog.detail\" : \n+ \"config.slog.timers\" : \n+ \"config.slog.aux\" : \n+ \"config.*.*\" : (optional)\n+\n+ \"timers\" : (optional)\n+ \"aux\" : (optional)\n+\n+ \"child_summary\" : (optional)\n+\n+ is the value passed to exit() or returned from main().\n+\n+ is an array of messages passed to the die()\n+ and error() functions.\n+\n+ is the elapsed time from start until exit()\n+ was called or main() returned.\n+\n+ is the elapsed time from start until the slog\n+ atexit routine was called. This time will include any time\n+ required to shut down or wait for the pager to complete.\n+\n+ is present if the command was stopped by a single,\n+ such as a SIGPIPE when the pager is quit.\n+\n+ is the git version number as reported by \"git version\".\n+\n+ is the SLOG format version.\n+\n+ are the values of the corresponding\n+ \"slog.{detail,timers,aux}\" config setting. Since these values\n+ control optional SLOG features and filtering, these are present\n+ to help post-processors know if an expected event did not happen\n+ or was simply filtered out. (Described later)\n+\n+ is a place for developers to add additional\n+ important config settings to the log. This is not intended as a\n+ dumping ground for all config settings, but rather only ones that\n+ might affect performance or allow A/B testing in production.\n+\n+ is a structure of any SLOG timers used during the process.\n+ (Described later)\n+\n+ is a structure of any \"aux data\" generated during the process.\n+ (Described later)\n+\n+ is a structure summarizing child processes by class.\n+ (Described later)\n+\n+\n+\"event\": \"detail\" and config setting \"slog.detail\"\n+--------------------------------------------------\n+\n+The \"detail\" event is used to report progress and/or debug information\n+during a command. It is a line-by-line (rather than summary) event.\n+Like GIT_TRACE_, detail events are classified by \"category\" and\n+may be included or omitted based on the \"slog.detail\" config setting.\n+\n+Here are 3 example \"detail\" events:\n+\n+{\n+ \"event\": \"detail\",\n+ \"clock_us\": 1530273485479387,\n+ \"pid\": 107253,\n+ \"sid\": \"1530273485473820-107253\",\n+ \"command\": \"status\",\n+ \"detail\": {\n+ \"category\": \"index\",\n+ \"label\": \"lazy_init_name_hash\",\n+ \"data\": {\n+ \"cache_nr\": 3269,\n+ \"elapsed_us\": 195,\n+ \"dir_count\": 0,\n+ \"dir_tablesize\": 4096,\n+ \"name_count\": 3269,\n+ \"name_tablesize\": 4096\n+ }\n+ }\n+}\n+{\n+ \"event\": \"detail\",\n+ \"clock_us\": 1530283184051338,\n+ \"pid\": 109679,\n+ \"sid\": \"1530283180782876-109679\",\n+ \"command\": \"fetch\",\n+ \"detail\": {\n+ \"category\": \"child\",\n+ \"label\": \"child_starting\",\n+ \"data\": {\n+ \"child_id\": 3,\n+ \"git_cmd\": true,\n+ \"use_shell\": false,\n+ \"is_interactive\": false,\n+ \"child_argv\": [\n+ \"gc\",\n+ \"--auto\"\n+ ]\n+ }\n+ }\n+}\n+{\n+ \"event\": \"detail\",\n+ \"clock_us\": 1530283184053158,\n+ \"pid\": 109679,\n+ \"sid\": \"1530283180782876-109679\",\n+ \"command\": \"fetch\",\n+ \"detail\": {\n+ \"category\": \"child\",\n+ \"label\": \"child_ended\",\n+ \"data\": {\n+ \"child_id\": 3,\n+ \"git_cmd\": true,\n+ \"use_shell\": false,\n+ \"is_interactive\": false,\n+ \"child_argv\": [\n+ \"gc\",\n+ \"--auto\"\n+ ],\n+ \"child_pid\": 109684,\n+ \"child_exit_code\": 0,\n+ \"child_elapsed_us\": 1819\n+ }\n+ }\n+}\n+\n+A detail event contains the common F1 described earlier. It also\n+contains 2 fixed fields and 1 variable field:\n+\n+ \"detail.category\" : \n+ \"detail.label\" : \n+ \"detail.data\" : \n+\n+ is the \"category\" name for the event. This is\n+ similar to GIT_TRACE_. In the example above we have 1\n+ \"index\" and 2 \"child\" category events.\n+\n+ If the config setting \"slog.detail\" is true or contains this\n+ category name, the event will be generated. If \"slog.detail\"\n+ is false, no detail events will be generated.\n+\n+ $ git config slog.detail true\n+ $ git config slog.detail child,index,status\n+ $ git config slog.detail false\n+\n+ is a descriptive label for the event. It may be the\n+ name of a function or any meaningful value.\n+\n+ is a JSON structure containing context-specific data for\n+ the event. This replaces the need for printf-like trace messages.\n+\n+\n+Child Detail Events\n+-------------------\n+\n+Child detail events build upon the generic detail event and are used\n+to log information about spawned child processes.\n+\n+A \"child_starting\" detail event is generated immediately before\n+spawning a child process.\n+\n+ \"event\" : \"detail:\n+ \"detail.category\" : \"child\"\n+ \"detail.label\" : \"child_starting\"\n+\n+ \"detail.data.child_id\" : \n+ \"detail.data.git_cmd\" : \n+ \"detail.data.use_shell\" : \n+ \"detail.data.is_interactive\" : \n+ \"detail.data.child_class\" : \n+ \"detail.data.child_argv\" : \n+\n+ is a simple integer id number for the child. This helps\n+ match up the \"child_starting\" and \"child_ended\" detail events.\n+ (The child's PID is not available until it is started.)\n+\n+ is true if git will try to run the command as a git\n+ command. The reported argv[0] for the child is probably a git\n+ command verb rather than \"git\".\n+\n+ is true if gill will try to use the shell to run the\n+ command.\n+\n+ is true if the child is considered interactive.\n+ Editor and pager processes are considered interactive.\n+\n+ is a classification for the child process, such as\n+ \"editor\", \"pager\", and \"shell\".\n+\n+ is the array of arguments to be passed to the child.\n+\n+\n+A \"child_ended\" detail event is generated after the child process\n+terminates and has been reaped.\n+\n+ \"event\" : \"detail:\n+ \"detail.category\" : \"child\"\n+ \"detail.label\" : \"child_ended\"\n+\n+ \"detail.data.child_id\" : \n+ \"detail.data.git_cmd\" : \n+ \"detail.data.use_shell\" : \n+ \"detail.data.is_interactive\" : \n+ \"detail.data.child_class\" : \n+ \"detail.data.child_argv\" : \n+\n+ \"detail.data.child_pid\" : \n+ \"detail.data.child_exit_code\" : \n+ \"detail.data.child_elapsed_us\" : \n+\n+ is the OS process-id for the child process.\n+\n+ is the child's exit code.\n+\n+ is the elapsed time in microseconds since the\n+ \"child_starting\" event was generated. This is the observed time\n+ the current process waited for the child to complete. This value\n+ will be slightly larger than the value that the child process\n+ reports for itself.\n+\n+\n+Child Summary Data \n+==================================\n+\n+If child processes are spawned, a summary is written to the \"cmd_exit\"\n+event. (This is written even if child detail events are disabled.)\n+The summary is grouped by child class (editor, pager, etc.) and contains\n+the number of child processes and their total elapsed time.\n+\n+For example:\n+\n+{\n+ \"event\": \"cmd_exit\",\n+ ...,\n+ \"child_summary\": {\n+ \"pager\": {\n+ \"total_us\": 14994045,\n+ \"count\": 1\n+ }\n+ }\n+}\n+\n+ \"child_summary..total_us\" : \n+ \"child_summary..count\" : \n+\n+Note that the total child time may exceed the elapsed time for the\n+git process because child processes may have been run in parallel.\n+\n+\n+Timers and config setting \"slog.timers\"\n+================================================\n+\n+SLOG provides a stopwatch-like timer facility to easily instrument\n+small spans of code. These timers are automatically added to the\n+\"cmd_exit\" event. These are lighter weight than using explicit\n+\"detail\" events or git_trace_performance_since()-style messages.\n+Also, having timer data included in the \"cmd_exit\" event makes it\n+easier for some kinds of post-processing.\n+\n+For example:\n+\n+{\n+ \"event\": \"cmd_exit\",\n+ ...,\n+ \"timers\": {\n+ \"index\": {\n+ \"do_read_index\": {\n+ \"count\": 1,\n+ \"total_us\": 488\n+ },\n+ \"preload\": {\n+ \"count\": 1,\n+ \"total_us\": 2394\n+ }\n+ },\n+ \"status\": {\n+ \"changes_index\": {\n+ \"count\": 1,\n+ \"total_us\": 574\n+ },\n+ \"untracked\": {\n+ \"count\": 1,\n+ \"total_us\": 5877\n+ },\n+ \"worktree\": {\n+ \"count\": 1,\n+ \"total_us\": 92\n+ }\n+ }\n+ }\n+}\n+\n+Timers have a \"category\" and a \"name\". Timers may be enabled or\n+disabled by category (much like GIT_TRACE_). The \"slog.timers\"\n+config setting controls which timers are enabled. For example:\n+\n+ $ git config --local slog.timers true\n+ $ git config --local slog.timers index,status\n+ $ git config --local slog.timers false\n+\n+Data for the enabled timers is written in the \"cmd_exit\" event under\n+the \"timers\" structure. They are grouped by category. Each timer\n+contains the total elapsed time and the number of times the timer was\n+started. Min, max, and average times are included if the timer was\n+started/stopped more than once. And \"force_stop\" flag is set if the\n+timer was still running when the command finished.\n+\n+ \"timers...count\" : \n+ \"timers...total_us\" : \n+ \"timers...min_us\" : (optional)\n+ \"timers...max_us\" : (optional)\n+ \"timers...avg_us\" : (optional)\n+ \"timers...force_stop\" : (optional)\n+ \n+ \n+Aux Data and config setting \"slog.aux\"\n+============================================\n+\n+\"Aux\" data is intended as a generic container for context-specific\n+fields, such as information about the size or shape of the repository.\n+This data is automatically added to the \"cmd_exit\" event. This is\n+data is lighter weight than using explicit detail events and may make\n+some kinds of post-processing easier.\n+\n+For example:\n+\n+{\n+ \"event\": \"cmd_exit\",\n+ ...,\n+ \"aux\": {\n+ \"index\": [\n+ [\n+ \"cache_nr\",\n+ 3269\n+ ],\n+ [\n+ \"sparse_checkout_count\",\n+ 1\n+ ]\n+ ]\n+ }\n+\n+\n+This API adds additional key/value pairs to the \"cmd_exit\" summary\n+data. Value may be scalars or any JSON structure or array.\n+\n+Like detail events and timers, each key/value pair is associated with\n+a \"category\" (much like GIT_TRACE_). The \"slog.aux\" config\n+setting controls which pairs are written or omitted. For example:\n+\n+ $ git config --local slog.aux true\n+ $ git config --local slog.aux index\n+ $ git config --local slog.aux false\n+\n+Aux data is written in the \"cmd_exit\" event under the \"aux\" structure\n+and are grouped by category. Each key/value pair is written as an\n+array rather than a structure to allow for duplicate keys.\n+\n+ \"aux.\" : [ , , ... ]\n+\n+ is 2-element array of [ , ].\n+\n+\n+Session-Id \n+=======================\n+\n+A session id (SID) is a cheap, unique-enough string to associate all\n+of the events generated by a single process. A child git process inherits\n+the SID of their parent git process and incorporates it into their SID.\n+\n+SIDs are constructed as:\n+\n+ SID ::= '-' [ ':' ]\n+\n+This scheme is used rather than a simple PID or {PPID, PID} because\n+PIDs are recycled by the OS (after sufficient time). This also allows\n+a git child process to be associated with their git parent process\n+even when there is an intermediate shell process.\n+\n+Note: we could use UUIDs or GUIDs for this, but that seemed overkill\n+at this point. It also required platform-specific code to generate\n+which muddied up the code.\n+\n+\n+Detailed Example\n+================\n+\n+Here is a longer example for `git status` with all optional settings\n+turned on:\n+\n+ $ git config slog.detail true\n+ $ git config slog.timers true\n+ $ git config slog.aux true\n+\n+ $ git status\n+\n+ # A \"cmd_start\" event is written when the command starts.\n+\n+{\n+ \"event\": \"cmd_start\",\n+ \"clock_us\": 1531499671154813,\n+ \"pid\": 14667,\n+ \"sid\": \"1531499671154813-14667\",\n+ \"command\": \"status\",\n+ \"argv\": [\n+ \"./git\",\n+ \"status\"\n+ ]\n+}\n+\n+ # An example detail event was added to lazy_init_name_hash() to\n+ # dump the size of the index and the resulting hash tables.\n+\n+{\n+ \"event\": \"detail\",\n+ \"clock_us\": 1531499671161042,\n+ \"pid\": 14667,\n+ \"sid\": \"1531499671154813-14667\",\n+ \"command\": \"status\",\n+ \"detail\": {\n+ \"category\": \"index\",\n+ \"label\": \"lazy_init_name_hash\",\n+ \"data\": {\n+ \"cache_nr\": 3266,\n+ \"elapsed_us\": 214,\n+ \"dir_count\": 0,\n+ \"dir_tablesize\": 4096,\n+ \"name_count\": 3266,\n+ \"name_tablesize\": 4096\n+ }\n+ }\n+}\n+\n+ # The \"cmd_exit\" event includes the command result and elapsed\n+ # time and the various configuration settings. During the run\n+ # \"index\" category timers were placed around the do_read_index()\n+ # and \"preload()\" calls and various \"status\" category timers were\n+ # placed around the 3 major parts of the status computation.\n+ # Lastly, an \"index\" category \"aux\" data item was added to report\n+ # the size of the index.\n+\n+{\n+ \"event\": \"cmd_exit\",\n+ \"clock_us\": 1531499671168303,\n+ \"pid\": 14667,\n+ \"sid\": \"1531499671154813-14667\",\n+ \"command\": \"status\",\n+ \"argv\": [\n+ \"./git\",\n+ \"status\"\n+ ],\n+ \"result\": {\n+ \"exit_code\": 0,\n+ \"elapsed_core_us\": 13488,\n+ \"elapsed_total_us\": 13490\n+ },\n+ \"version\": {\n+ \"git\": \"2.18.0.26.gebaccfc\",\n+ \"slog\": 0\n+ },\n+ \"config\": {\n+ \"slog\": {\n+ \"detail\": 1,\n+ \"timers\": 1,\n+ \"aux\": 1\n+ }\n+ },\n+ \"timers\": {\n+ \"index\": {\n+ \"do_read_index\": {\n+ \"count\": 1,\n+ \"total_us\": 553\n+ },\n+ \"preload\": {\n+ \"count\": 1,\n+ \"total_us\": 2892\n+ }\n+ },\n+ \"status\": {\n+ \"changes_index\": {\n+ \"count\": 1,\n+ \"total_us\": 778\n+ },\n+ \"untracked\": {\n+ \"count\": 1,\n+ \"total_us\": 6136\n+ },\n+ \"worktree\": {\n+ \"count\": 1,\n+ \"total_us\": 106\n+ }\n+ }\n+ },\n+ \"aux\": {\n+ \"index\": [\n+ [\n+ \"cache_nr\",\n+ 3266\n+ ]\n+ ]\n+ }\n+}\n-- \n2.9.3\n\n"},{"id":"352482","messageId":"20180713165621.52017-5-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 04/25] structured-logging: add session-id to log events","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:56:00Z","receivedAt":"2018-07-13T16:56:35Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nTeach git to create a unique session id (SID) during structured\nlogging initialization and use that SID in all log events.\n\nThis SID is exported into a transient environment variable and\ninherited by child processes. This allows git child processes\nto be related back to the parent git process event if there are\nintermediate /bin/sh processes between them.\n\nUpdate t0001 to ignore the environment variable GIT_SLOG_PARENT_SID.\n\nSigned-off-by: Jeff Hostetler \n---\n Documentation/git.txt | 6 ++++++\n structured-logging.c | 52 +++++++++++++++++++++++++++++++++++++++++++++++++++\n t/t0001-init.sh | 1 +\n 3 files changed, 59 insertions(+)\n\ndiff --git a/Documentation/git.txt b/Documentation/git.txt\nindex dba7f0c..a24f399 100644\n--- a/Documentation/git.txt\n+++ b/Documentation/git.txt\n@@ -766,6 +766,12 @@ standard output.\n \tadequate and support for it is likely to be removed in the\n \tforeseeable future (along with the variable).\n \n+`GIT_SLOG_PARENT_SID`::\n+\t(Experimental) A transient environment variable set by top-level\n+\tGit commands and inherited by child Git commands. It contains\n+\ta session id that will be written the structured logging output\n+\tto help associate child and parent processes.\n+\n Discussion[[Discussion]]\n ------------------------\n \ndiff --git a/structured-logging.c b/structured-logging.c\nindex afa2224..289140f 100644\n--- a/structured-logging.c\n+++ b/structured-logging.c\n@@ -31,9 +31,57 @@ static char *my__command_name;\n static char *my__sub_command_name;\n \n static struct argv_array my__argv = ARGV_ARRAY_INIT;\n+static struct strbuf my__session_id = STRBUF_INIT;\n static struct json_writer my__errors = JSON_WRITER_INIT;\n \n /*\n+ * Compute a new session id for the current process. Build string\n+ * with the start time and PID of the current process and append\n+ * the inherited session id from our parent process (if present).\n+ * The parent session id may include its parent session id.\n+ *\n+ * sid := '-' [ ':' [ ... ] ]\n+ */\n+static void compute_our_sid(void)\n+{\n+\tconst char *parent_sid;\n+\n+\tif (my__session_id.len)\n+\t\treturn;\n+\n+\t/*\n+\t * A \"session id\" (SID) is a cheap, unique-enough string to\n+\t * associate child process with the hierarchy of invoking git\n+\t * processes.\n+\t *\n+\t * This is stronger than a simple parent-pid because we may\n+\t * have an intermediate shell between a top-level Git command\n+\t * and a child Git command. It also isolates from issues\n+\t * about how the OS recycles PIDs.\n+\t *\n+\t * This could be a UUID/GUID, but that is overkill for our\n+\t * needs here and more expensive to compute.\n+\t *\n+\t * Consumers should consider this an unordered opaque string\n+\t * in case we decide to switch to a real UUID in the future.\n+\t */\n+\tstrbuf_addf(&my__session_id, \"%\"PRIuMAX\"-%\"PRIdMAX,\n+\t\t (uintmax_t)my__start_time, (intmax_t)my__pid);\n+\n+\tparent_sid = getenv(\"GIT_SLOG_PARENT_SID\");\n+\tif (parent_sid && *parent_sid) {\n+\t\tstrbuf_addch(&my__session_id, ':');\n+\t\tstrbuf_addstr(&my__session_id, parent_sid);\n+\t}\n+\n+\t/*\n+\t * Install our SID into the environment for our child processes\n+\t * to inherit.\n+\t */\n+\tsetenv(\"GIT_SLOG_PARENT_SID\", my__session_id.buf, 1);\n+}\n+\n+/*\n * Write a single event to the structured log file.\n */\n static void emit_event(struct json_writer *jw, const char *event_name)\n@@ -75,6 +123,7 @@ static void emit_start_event(void)\n \t\tjw_object_string(&jw, \"event\", \"cmd_start\");\n \t\tjw_object_intmax(&jw, \"clock_us\", (intmax_t)my__start_time);\n \t\tjw_object_intmax(&jw, \"pid\", (intmax_t)my__pid);\n+\t\tjw_object_string(&jw, \"sid\", my__session_id.buf);\n \n \t\tif (my__command_name && *my__command_name)\n \t\t\tjw_object_string(&jw, \"command\", my__command_name);\n@@ -112,6 +161,7 @@ static void emit_exit_event(void)\n \t\tjw_object_string(&jw, \"event\", \"cmd_exit\");\n \t\tjw_object_intmax(&jw, \"clock_us\", (intmax_t)atexit_time);\n \t\tjw_object_intmax(&jw, \"pid\", (intmax_t)my__pid);\n+\t\tjw_object_string(&jw, \"sid\", my__session_id.buf);\n \n \t\tif (my__command_name && *my__command_name)\n \t\t\tjw_object_string(&jw, \"command\", my__command_name);\n@@ -250,6 +300,7 @@ static void do_final_steps(int in_signal)\n \tfree(my__sub_command_name);\n \targv_array_clear(&my__argv);\n \tjw_release(&my__errors);\n+\tstrbuf_release(&my__session_id);\n }\n \n static void slog_atexit(void)\n@@ -289,6 +340,7 @@ static void initialize(int argc, const char **argv)\n {\n \tmy__start_time = getnanotime() / 1000;\n \tmy__pid = getpid();\n+\tcompute_our_sid();\n \n \tintern_argv(argc, argv);\n \ndiff --git a/t/t0001-init.sh b/t/t0001-init.sh\nindex c413bff..3dfc37a 100755\n--- a/t/t0001-init.sh\n+++ b/t/t0001-init.sh\n@@ -92,6 +92,7 @@ test_expect_success 'No extra GIT_* on alias scripts' '\n \tenv |\n \t\tsed -n \\\n \t\t\t-e \"/^GIT_PREFIX=/d\" \\\n+\t\t\t-e \"/^GIT_SLOG_PARENT_SID=/d\" \\\n \t\t\t-e \"/^GIT_TEXTDOMAINDIR=/d\" \\\n \t\t\t-e \"/^GIT_/s/=.*//p\" |\n \t\tsort\n-- \n2.9.3\n\n"},{"id":"352483","messageId":"20180713165621.52017-7-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 06/25] structured-logging: set sub_command field for checkout command","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:56:02Z","receivedAt":"2018-07-13T16:56:36Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nSigned-off-by: Jeff Hostetler \n---\n builtin/checkout.c | 7 +++++++\n 1 file changed, 7 insertions(+)\n\ndiff --git a/builtin/checkout.c b/builtin/checkout.c\nindex 2e1d237..d05890b 100644\n--- a/builtin/checkout.c\n+++ b/builtin/checkout.c\n@@ -249,6 +249,8 @@ static int checkout_paths(const struct checkout_opts *opts,\n \tint errs = 0;\n \tstruct lock_file lock_file = LOCK_INIT;\n \n+\tslog_set_sub_command_name(opts->patch_mode ? \"patch\" : \"path\");\n+\n \tif (opts->track != BRANCH_TRACK_UNSPECIFIED)\n \t\tdie(_(\"'%s' cannot be used with updating paths\"), \"--track\");\n \n@@ -826,6 +828,9 @@ static int switch_branches(const struct checkout_opts *opts,\n \tvoid *path_to_free;\n \tstruct object_id rev;\n \tint flag, writeout_error = 0;\n+\n+\tslog_set_sub_command_name(\"switch_branch\");\n+\n \tmemset(&old_branch_info, 0, sizeof(old_branch_info));\n \told_branch_info.path = path_to_free = resolve_refdup(\"HEAD\", 0, &rev, &flag);\n \tif (old_branch_info.path)\n@@ -1037,6 +1042,8 @@ static int switch_unborn_to_new_branch(const struct checkout_opts *opts)\n \tint status;\n \tstruct strbuf branch_ref = STRBUF_INIT;\n \n+\tslog_set_sub_command_name(\"switch_unborn_to_new_branch\");\n+\n \tif (!opts->new_branch)\n \t\tdie(_(\"You are on a branch yet to be born\"));\n \tstrbuf_addf(&branch_ref, \"refs/heads/%s\", opts->new_branch);\n-- \n2.9.3\n\n"},{"id":"352484","messageId":"20180713165621.52017-9-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 08/25] structured-logging: add detail-event facility","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:56:04Z","receivedAt":"2018-07-13T16:56:37Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nAdd a generic \"detail-event\" to structured logging. This can be used\nto emit context-specific events for performance or debugging purposes.\nThese are conceptually similar to the various GIT_TRACE_ messages.\n\nSigned-off-by: Jeff Hostetler \n---\n Documentation/config.txt | 13 +++++++\n structured-logging.c | 95 ++++++++++++++++++++++++++++++++++++++++++++++++\n structured-logging.h | 16 ++++++++\n 3 files changed, 124 insertions(+)\n\ndiff --git a/Documentation/config.txt b/Documentation/config.txt\nindex c79f2bf..88f93fe 100644\n--- a/Documentation/config.txt\n+++ b/Documentation/config.txt\n@@ -3176,6 +3176,19 @@ slog.pretty::\n \t(EXPERIMENTAL) Pretty-print structured log data when true.\n \t(Git must be compiled with STRUCTURED_LOGGING=1.)\n \n+slog.detail::\n+\t(EXPERIMENTAL) May be set to a boolean value or a list of comma\n+\tseparated tokens. Controls which categories of optional \"detail\"\n+\tevents are generated. Default to off. This is conceptually\n+\tsimilar to the different GIT_TRACE_ values.\n++\n+Detail events are generic events with a context-specific payload. This\n+may represent a single function call or a section of performance sensitive\n+code.\n++\n+This is intended to be an extendable facility where new events can easily\n+be added (possibly only for debugging or performance testing purposes).\n+\n splitIndex.maxPercentChange::\n \tWhen the split index feature is used, this specifies the\n \tpercent of entries the split index can contain compared to the\ndiff --git a/structured-logging.c b/structured-logging.c\nindex 289140f..9cbf3bd 100644\n--- a/structured-logging.c\n+++ b/structured-logging.c\n@@ -34,6 +34,34 @@ static struct argv_array my__argv = ARGV_ARRAY_INIT;\n static struct strbuf my__session_id = STRBUF_INIT;\n static struct json_writer my__errors = JSON_WRITER_INIT;\n \n+struct category_filter\n+{\n+\tchar *categories;\n+\tint want;\n+};\n+\n+static struct category_filter my__detail_categories;\n+\n+static void set_want_categories(struct category_filter *cf, const char *value)\n+{\n+\tFREE_AND_NULL(cf->categories);\n+\n+\tcf->want = git_parse_maybe_bool(value);\n+\tif (cf->want == -1)\n+\t\tcf->categories = xstrdup(value);\n+}\n+\n+static int want_category(const struct category_filter *cf, const char *category)\n+{\n+\tif (cf->want == 0 || cf->want == 1)\n+\t\treturn cf->want;\n+\n+\tif (!category || !*category)\n+\t\treturn 0;\n+\n+\treturn !!strstr(cf->categories, category);\n+}\n+\n /*\n * Compute a new session id for the current process. Build string\n * with the start time and PID of the current process and append\n@@ -207,6 +235,40 @@ static void emit_exit_event(void)\n \tjw_release(&jw);\n }\n \n+static void emit_detail_event(const char *category, const char *label,\n+\t\t\t const struct json_writer *data)\n+{\n+\tstruct json_writer jw = JSON_WRITER_INIT;\n+\tuint64_t clock_us = getnanotime() / 1000;\n+\n+\t/* build \"detail\" event */\n+\tjw_object_begin(&jw, my__is_pretty);\n+\t{\n+\t\tjw_object_string(&jw, \"event\", \"detail\");\n+\t\tjw_object_intmax(&jw, \"clock_us\", (intmax_t)clock_us);\n+\t\tjw_object_intmax(&jw, \"pid\", (intmax_t)my__pid);\n+\t\tjw_object_string(&jw, \"sid\", my__session_id.buf);\n+\n+\t\tif (my__command_name && *my__command_name)\n+\t\t\tjw_object_string(&jw, \"command\", my__command_name);\n+\t\tif (my__sub_command_name && *my__sub_command_name)\n+\t\t\tjw_object_string(&jw, \"sub_command\", my__sub_command_name);\n+\n+\t\tjw_object_inline_begin_object(&jw, \"detail\");\n+\t\t{\n+\t\t\tjw_object_string(&jw, \"category\", category);\n+\t\t\tjw_object_string(&jw, \"label\", label);\n+\t\t\tif (data)\n+\t\t\t\tjw_object_sub_jw(&jw, \"data\", data);\n+\t\t}\n+\t\tjw_end(&jw);\n+\t}\n+\tjw_end(&jw);\n+\n+\temit_event(&jw, \"detail\");\n+\tjw_release(&jw);\n+}\n+\n static int cfg_path(const char *key, const char *value)\n {\n \tif (is_absolute_path(value)) {\n@@ -226,6 +288,12 @@ static int cfg_pretty(const char *key, const char *value)\n \treturn 0;\n }\n \n+static int cfg_detail(const char *key, const char *value)\n+{\n+\tset_want_categories(&my__detail_categories, value);\n+\treturn 0;\n+}\n+\n int slog_default_config(const char *key, const char *value)\n {\n \tconst char *sub;\n@@ -244,6 +312,8 @@ int slog_default_config(const char *key, const char *value)\n \t\t\treturn cfg_path(key, value);\n \t\tif (!strcmp(sub, \"pretty\"))\n \t\t\treturn cfg_pretty(key, value);\n+\t\tif (!strcmp(sub, \"detail\"))\n+\t\t\treturn cfg_detail(key, value);\n \t}\n \n \treturn 0;\n@@ -424,4 +494,29 @@ void slog_error_message(const char *prefix, const char *fmt, va_list params)\n \tstrbuf_release(&em);\n }\n \n+int slog_want_detail_event(const char *category)\n+{\n+\treturn want_category(&my__detail_categories, category);\n+}\n+\n+void slog_emit_detail_event(const char *category, const char *label,\n+\t\t\t const struct json_writer *data)\n+{\n+\tif (!my__wrote_start_event)\n+\t\temit_start_event();\n+\n+\tif (!slog_want_detail_event(category))\n+\t\treturn;\n+\n+\tif (!category || !*category)\n+\t\tBUG(\"no category for slog.detail event\");\n+\tif (!label || !*label)\n+\t\tBUG(\"no label for slog.detail event\");\n+\tif (data && !jw_is_terminated(data))\n+\t\tBUG(\"unterminated slog.detail data: '%s' '%s' '%s'\",\n+\t\t category, label, data->json.buf);\n+\n+\temit_detail_event(category, label, data);\n+}\n+\n #endif\ndiff --git a/structured-logging.h b/structured-logging.h\nindex 61e98e6..01ae55d 100644\n--- a/structured-logging.h\n+++ b/structured-logging.h\n@@ -1,6 +1,8 @@\n #ifndef STRUCTURED_LOGGING_H\n #define STRUCTURED_LOGGING_H\n \n+struct json_writer;\n+\n typedef int (*slog_fn_main_t)(int, const char **);\n \n #if !defined(STRUCTURED_LOGGING)\n@@ -17,6 +19,8 @@ typedef int (*slog_fn_main_t)(int, const char **);\n #define slog_is_pretty() (0)\n #define slog_exit_code(exit_code) (exit_code)\n #define slog_error_message(prefix, fmt, params) do { } while (0)\n+#define slog_want_detail_event(category) (0)\n+#define slog_emit_detail_event(category, label, data) do { } while (0)\n \n #else\n \n@@ -91,5 +95,17 @@ int slog_exit_code(int exit_code);\n */\n void slog_error_message(const char *prefix, const char *fmt, va_list params);\n \n+/*\n+ * Is detail logging enabled for this category?\n+ */\n+int slog_want_detail_event(const char *category);\n+\n+/*\n+ * Write a detail event.\n+ */\n+\n+void slog_emit_detail_event(const char *category, const char *label,\n+\t\t\t const struct json_writer *data);\n+\n #endif /* STRUCTURED_LOGGING */\n #endif /* STRUCTURED_LOGGING_H */\n-- \n2.9.3\n\n"},{"id":"352485","messageId":"20180713165621.52017-8-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 07/25] structured-logging: t0420 basic tests","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:56:03Z","receivedAt":"2018-07-13T16:56:38Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nAdd structured logging prereq definition \"SLOG\" to test-lib.sh.\nCreate t0420 test script with some basic tests.\n\nSigned-off-by: Jeff Hostetler \n---\n t/t0420-structured-logging.sh | 143 ++++++++++++++++++++++++++++++++++++++++++\n t/t0420/parse_json.perl | 52 +++++++++++++++\n t/test-lib.sh | 1 +\n 3 files changed, 196 insertions(+)\n create mode 100755 t/t0420-structured-logging.sh\n create mode 100644 t/t0420/parse_json.perl\n\ndiff --git a/t/t0420-structured-logging.sh b/t/t0420-structured-logging.sh\nnew file mode 100755\nindex 0000000..a594af3\n--- /dev/null\n+++ b/t/t0420-structured-logging.sh\n@@ -0,0 +1,143 @@\n+#!/bin/sh\n+\n+test_description='structured logging tests'\n+\n+. ./test-lib.sh\n+\n+if ! test_have_prereq SLOG\n+then\n+\tskip_all='skipping structured logging tests'\n+\ttest_done\n+fi\n+\n+LOGFILE=$TRASH_DIRECTORY/test.log\n+\n+test_expect_success 'setup' '\n+\ttest_commit hello &&\n+\tcat >key_cmd_start <<-\\EOF &&\n+\t\"event\":\"cmd_start\"\n+\tEOF\n+\tcat >key_cmd_exit <<-\\EOF &&\n+\t\"event\":\"cmd_exit\"\n+\tEOF\n+\tcat >key_exit_code_0 <<-\\EOF &&\n+\t\"exit_code\":0\n+\tEOF\n+\tcat >key_exit_code_129 <<-\\EOF &&\n+\t\"exit_code\":129\n+\tEOF\n+\tgit config --local slog.pretty false &&\n+\tgit config --local slog.path \"$LOGFILE\"\n+'\n+\n+test_expect_success 'basic events' '\n+\ttest_when_finished \"rm \\\"$LOGFILE\\\"\" &&\n+\tgit status >/dev/null &&\n+\tgrep -f key_cmd_start \"$LOGFILE\" &&\n+\tgrep -f key_cmd_exit \"$LOGFILE\" &&\n+\tgrep -f key_exit_code_0 \"$LOGFILE\"\n+'\n+\n+test_expect_success 'basic error code and message' '\n+\ttest_when_finished \"rm \\\"$LOGFILE\\\" event_exit\" &&\n+\ttest_expect_code 129 git status --xyzzy >/dev/null 2>/dev/null &&\n+\tgrep -f key_cmd_exit \"$LOGFILE\" >event_exit &&\n+\tgrep -f key_exit_code_129 event_exit &&\n+\tgrep \"\\\"errors\\\":\" event_exit\n+'\n+\n+test_lazy_prereq PERLJSON '\n+\tperl -MJSON -e \"exit 0\"\n+'\n+\n+# Let perl parse the resulting JSON and dump it out.\n+#\n+# Since the output contains PIDs, SIDs, clock values, and the full path to\n+# git[.exe] we cannot have a HEREDOC with the expected result, so we look\n+# for a few key fields.\n+#\n+test_expect_success PERLJSON 'parse JSON for basic command' '\n+\ttest_when_finished \"rm \\\"$LOGFILE\\\" event_exit\" &&\n+\tgit status >/dev/null &&\n+\n+\tgrep -f key_cmd_exit \"$LOGFILE\" >event_exit &&\n+\n+\tperl \"$TEST_DIRECTORY\"/t0420/parse_json.perl parsed_exit &&\n+\n+\tgrep \"row\\[0\\]\\.version\\.slog 0\" /dev/null &&\n+\tgit branch --all >/dev/null &&\n+\tgit branch new_branch >/dev/null &&\n+\n+\tgrep -f key_cmd_exit \"$LOGFILE\" >event_exit &&\n+\n+\tperl \"$TEST_DIRECTORY\"/t0420/parse_json.perl parsed_exit &&\n+\n+\tgrep \"row\\[0\\]\\.version\\.slog 0\" /dev/null &&\n+\tgit checkout master >/dev/null &&\n+\tgit checkout -- hello.t >/dev/null &&\n+\n+\tgrep -f key_cmd_exit \"$LOGFILE\" >event_exit &&\n+\n+\tperl \"$TEST_DIRECTORY\"/t0420/parse_json.perl parsed_exit &&\n+\n+\tgrep \"row\\[0\\]\\.version\\.slog 0\" 0) ? \"$label_in.$k\" : \"$k\";\n+\tmy $value = $obj{$k};\n+\n+\tdump_item($label, $value);\n+ }\n+}\n+\n+sub dump_item {\n+ my ($label_in, $value) = @_;\n+ if (ref($value) eq 'ARRAY') {\n+\tprint \"$label_in array\\n\";\n+\tdump_array($label_in, $value);\n+ } elsif (ref($value) eq 'HASH') {\n+\tprint \"$label_in hash\\n\";\n+\tdump_hash($label_in, $value);\n+ } elsif (defined $value) {\n+\tprint \"$label_in $value\\n\";\n+ } else {\n+\tprint \"$label_in null\\n\";\n+ }\n+}\n+\n+my $row = 0;\n+while (<>) {\n+ my $data = decode_json( $_ );\n+ my $label = \"row[$row]\";\n+\n+ dump_hash($label, $data);\n+ $row++;\n+}\n+\ndiff --git a/t/test-lib.sh b/t/test-lib.sh\nindex 2831570..3d38bc7 100644\n--- a/t/test-lib.sh\n+++ b/t/test-lib.sh\n@@ -1071,6 +1071,7 @@ test -n \"$USE_LIBPCRE1$USE_LIBPCRE2\" && test_set_prereq PCRE\n test -n \"$USE_LIBPCRE1\" && test_set_prereq LIBPCRE1\n test -n \"$USE_LIBPCRE2\" && test_set_prereq LIBPCRE2\n test -z \"$NO_GETTEXT\" && test_set_prereq GETTEXT\n+test -z \"$STRUCTURED_LOGGING\" || test_set_prereq SLOG\n \n # Can we rely on git's output in the C locale?\n if test -n \"$GETTEXT_POISON\"\n-- \n2.9.3\n\n"},{"id":"352486","messageId":"20180713165621.52017-11-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 10/25] structured-logging: add timer facility","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:56:06Z","receivedAt":"2018-07-13T16:56:39Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nAdd timer facility to structured logging. This allows stopwatch-like\noperations over the life of the git process. Timer data is summarized\nin the \"cmd_exit\" event.\n\nSigned-off-by: Jeff Hostetler \n---\n Documentation/config.txt | 6 ++\n structured-logging.c | 180 +++++++++++++++++++++++++++++++++++++++++++++++\n structured-logging.h | 19 +++++\n 3 files changed, 205 insertions(+)\n\ndiff --git a/Documentation/config.txt b/Documentation/config.txt\nindex 88f93fe..7817966 100644\n--- a/Documentation/config.txt\n+++ b/Documentation/config.txt\n@@ -3189,6 +3189,12 @@ code.\n This is intended to be an extendable facility where new events can easily\n be added (possibly only for debugging or performance testing purposes).\n \n+slog.timers::\n+\t(EXPERIMENTAL) May be set to a boolean value or a list of comma\n+\tseparated tokens. Controls which categories of SLOG timers are\n+\tenabled. Defaults to off. Data for enabled timers is added to\n+\tthe `cmd_exit` event.\n+\n splitIndex.maxPercentChange::\n \tWhen the split index feature is used, this specifies the\n \tpercent of entries the split index can contain compared to the\ndiff --git a/structured-logging.c b/structured-logging.c\nindex 9cbf3bd..215138c 100644\n--- a/structured-logging.c\n+++ b/structured-logging.c\n@@ -15,6 +15,26 @@\n \n #define SLOG_VERSION 0\n \n+struct timer_data {\n+\tchar *category;\n+\tchar *name;\n+\tuint64_t total_ns;\n+\tuint64_t min_ns;\n+\tuint64_t max_ns;\n+\tuint64_t start_ns;\n+\tint count;\n+\tint started;\n+};\n+\n+struct timer_data_array {\n+\tstruct timer_data **array;\n+\tsize_t nr, alloc;\n+};\n+\n+static struct timer_data_array my__timers;\n+static void format_timers(struct json_writer *jw);\n+static void free_timers(void);\n+\n static uint64_t my__start_time;\n static uint64_t my__exit_time;\n static int my__is_config_loaded;\n@@ -41,6 +61,7 @@ struct category_filter\n };\n \n static struct category_filter my__detail_categories;\n+static struct category_filter my__timer_categories;\n \n static void set_want_categories(struct category_filter *cf, const char *value)\n {\n@@ -228,6 +249,12 @@ static void emit_exit_event(void)\n \t\t\tjw_object_intmax(&jw, \"slog\", SLOG_VERSION);\n \t\t}\n \t\tjw_end(&jw);\n+\n+\t\tif (my__timers.nr) {\n+\t\t\tjw_object_inline_begin_object(&jw, \"timers\");\n+\t\t\tformat_timers(&jw);\n+\t\t\tjw_end(&jw);\n+\t\t}\n \t}\n \tjw_end(&jw);\n \n@@ -294,6 +321,12 @@ static int cfg_detail(const char *key, const char *value)\n \treturn 0;\n }\n \n+static int cfg_timers(const char *key, const char *value)\n+{\n+\tset_want_categories(&my__timer_categories, value);\n+\treturn 0;\n+}\n+\n int slog_default_config(const char *key, const char *value)\n {\n \tconst char *sub;\n@@ -314,6 +347,8 @@ int slog_default_config(const char *key, const char *value)\n \t\t\treturn cfg_pretty(key, value);\n \t\tif (!strcmp(sub, \"detail\"))\n \t\t\treturn cfg_detail(key, value);\n+\t\tif (!strcmp(sub, \"timers\"))\n+\t\t\treturn cfg_timers(key, value);\n \t}\n \n \treturn 0;\n@@ -371,6 +406,7 @@ static void do_final_steps(int in_signal)\n \targv_array_clear(&my__argv);\n \tjw_release(&my__errors);\n \tstrbuf_release(&my__session_id);\n+\tfree_timers();\n }\n \n static void slog_atexit(void)\n@@ -519,4 +555,148 @@ void slog_emit_detail_event(const char *category, const char *label,\n \temit_detail_event(category, label, data);\n }\n \n+int slog_start_timer(const char *category, const char *name)\n+{\n+\tint k;\n+\tstruct timer_data *td;\n+\n+\tif (!want_category(&my__timer_categories, category))\n+\t\treturn SLOG_UNDEFINED_TIMER_ID;\n+\tif (!name || !*name)\n+\t\treturn SLOG_UNDEFINED_TIMER_ID;\n+\n+\tfor (k = 0; k < my__timers.nr; k++) {\n+\t\ttd = my__timers.array[k];\n+\t\tif (!strcmp(category, td->category) && !strcmp(name, td->name))\n+\t\t\tgoto start_timer;\n+\t}\n+\n+\ttd = xcalloc(1, sizeof(struct timer_data));\n+\ttd->category = xstrdup(category);\n+\ttd->name = xstrdup(name);\n+\ttd->min_ns = UINT64_MAX;\n+\n+\tALLOC_GROW(my__timers.array, my__timers.nr + 1, my__timers.alloc);\n+\tmy__timers.array[my__timers.nr++] = td;\n+\n+start_timer:\n+\tif (td->started)\n+\t\tBUG(\"slog.timer '%s:%s' already started\",\n+\t\t td->category, td->name);\n+\n+\ttd->start_ns = getnanotime();\n+\ttd->started = 1;\n+\n+\treturn k;\n+}\n+\n+static void stop_timer(struct timer_data *td)\n+{\n+\tuint64_t delta_ns = getnanotime() - td->start_ns;\n+\n+\ttd->count++;\n+\ttd->total_ns += delta_ns;\n+\tif (delta_ns < td->min_ns)\n+\t\ttd->min_ns = delta_ns;\n+\tif (delta_ns > td->max_ns)\n+\t\ttd->max_ns = delta_ns;\n+\ttd->started = 0;\n+}\n+\n+void slog_stop_timer(int tid)\n+{\n+\tstruct timer_data *td;\n+\n+\tif (tid == SLOG_UNDEFINED_TIMER_ID)\n+\t\treturn;\n+\tif (tid >= my__timers.nr || tid < 0)\n+\t\tBUG(\"Invalid slog.timer id '%d'\", tid);\n+\n+\ttd = my__timers.array[tid];\n+\tif (!td->started)\n+\t\tBUG(\"slog.timer '%s:%s' not started\", td->category, td->name);\n+\n+\tstop_timer(td);\n+}\n+\n+static int sort_timers_cb(const void *a, const void *b)\n+{\n+\tstruct timer_data *td_a = *(struct timer_data **)a;\n+\tstruct timer_data *td_b = *(struct timer_data **)b;\n+\tint r;\n+\n+\tr = strcmp(td_a->category, td_b->category);\n+\tif (r)\n+\t\treturn r;\n+\treturn strcmp(td_a->name, td_b->name);\n+}\n+\n+static void format_a_timer(struct json_writer *jw, struct timer_data *td,\n+\t\t\t int force_stop)\n+{\n+\tjw_object_inline_begin_object(jw, td->name);\n+\t{\n+\t\tjw_object_intmax(jw, \"count\", td->count);\n+\t\tjw_object_intmax(jw, \"total_us\", td->total_ns / 1000);\n+\t\tif (td->count > 1) {\n+\t\t\tuint64_t avg_ns = td->total_ns / td->count;\n+\n+\t\t\tjw_object_intmax(jw, \"min_us\", td->min_ns / 1000);\n+\t\t\tjw_object_intmax(jw, \"max_us\", td->max_ns / 1000);\n+\t\t\tjw_object_intmax(jw, \"avg_us\", avg_ns / 1000);\n+\t\t}\n+\t\tif (force_stop)\n+\t\t\tjw_object_true(jw, \"force_stop\");\n+\t}\n+\tjw_end(jw);\n+}\n+\n+static void format_timers(struct json_writer *jw)\n+{\n+\tconst char *open_category = NULL;\n+\tint k;\n+\n+\tQSORT(my__timers.array, my__timers.nr, sort_timers_cb);\n+\n+\tfor (k = 0; k < my__timers.nr; k++) {\n+\t\tstruct timer_data *td = my__timers.array[k];\n+\t\tint force_stop = td->started;\n+\n+\t\tif (force_stop)\n+\t\t\tstop_timer(td);\n+\n+\t\tif (!open_category) {\n+\t\t\tjw_object_inline_begin_object(jw, td->category);\n+\t\t\topen_category = td->category;\n+\t\t}\n+\t\telse if (strcmp(open_category, td->category)) {\n+\t\t\tjw_end(jw);\n+\t\t\tjw_object_inline_begin_object(jw, td->category);\n+\t\t\topen_category = td->category;\n+\t\t}\n+\n+\t\tformat_a_timer(jw, td, force_stop);\n+\t}\n+\n+\tif (open_category)\n+\t\tjw_end(jw);\n+}\n+\n+static void free_timers(void)\n+{\n+\tint k;\n+\n+\tfor (k = 0; k < my__timers.nr; k++) {\n+\t\tstruct timer_data *td = my__timers.array[k];\n+\n+\t\tfree(td->category);\n+\t\tfree(td->name);\n+\t\tfree(td);\n+\t}\n+\n+\tFREE_AND_NULL(my__timers.array);\n+\tmy__timers.nr = 0;\n+\tmy__timers.alloc = 0;\n+}\n+\n #endif\ndiff --git a/structured-logging.h b/structured-logging.h\nindex 01ae55d..a29aa6e 100644\n--- a/structured-logging.h\n+++ b/structured-logging.h\n@@ -5,6 +5,8 @@ struct json_writer;\n \n typedef int (*slog_fn_main_t)(int, const char **);\n \n+#define SLOG_UNDEFINED_TIMER_ID (-1)\n+\n #if !defined(STRUCTURED_LOGGING)\n /*\n * Structured logging is not available.\n@@ -21,6 +23,8 @@ typedef int (*slog_fn_main_t)(int, const char **);\n #define slog_error_message(prefix, fmt, params) do { } while (0)\n #define slog_want_detail_event(category) (0)\n #define slog_emit_detail_event(category, label, data) do { } while (0)\n+#define slog_start_timer(category, name) (SLOG_UNDEFINED_TIMER_ID)\n+static inline void slog_stop_timer(int tid) { };\n \n #else\n \n@@ -107,5 +111,20 @@ int slog_want_detail_event(const char *category);\n void slog_emit_detail_event(const char *category, const char *label,\n \t\t\t const struct json_writer *data);\n \n+/*\n+ * Define and start or restart a structured logging timer. Stats for the\n+ * timer will be added to the \"cmd_exit\" event. Use a timer when you are\n+ * interested in the net time of an operation (such as part of a computation\n+ * in a loop) but don't want a detail event for each iteration.\n+ *\n+ * Returns a timer id.\n+ */\n+int slog_start_timer(const char *category, const char *name);\n+\n+/*\n+ * Stop the timer.\n+ */\n+void slog_stop_timer(int tid);\n+\n #endif /* STRUCTURED_LOGGING */\n #endif /* STRUCTURED_LOGGING_H */\n-- \n2.9.3\n\n"},{"id":"352488","messageId":"20180713165621.52017-13-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 12/25] structured-logging: add timer around do_write_index","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:56:08Z","receivedAt":"2018-07-13T16:56:40Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nUse a SLOG timer to record the time spend in do_write_index() and\nreport it in the \"cmd_exit\" event.\n\nSigned-off-by: Jeff Hostetler \n---\n read-cache.c | 5 +++++\n 1 file changed, 5 insertions(+)\n\ndiff --git a/read-cache.c b/read-cache.c\nindex df5dc87..7fe66b5 100644\n--- a/read-cache.c\n+++ b/read-cache.c\n@@ -2433,7 +2433,9 @@ static int commit_locked_index(struct lock_file *lk)\n static int do_write_locked_index(struct index_state *istate, struct lock_file *lock,\n \t\t\t\t unsigned flags)\n {\n+\tint slog_timer = slog_start_timer(\"index\", \"do_write_index\");\n \tint ret = do_write_index(istate, lock->tempfile, 0);\n+\tslog_stop_timer(slog_timer);\n \tif (ret)\n \t\treturn ret;\n \tif (flags & COMMIT_LOCK)\n@@ -2514,11 +2516,14 @@ static int clean_shared_index_files(const char *current_hex)\n static int write_shared_index(struct index_state *istate,\n \t\t\t struct tempfile **temp)\n {\n+\tint slog_tid = SLOG_UNDEFINED_TIMER_ID;\n \tstruct split_index *si = istate->split_index;\n \tint ret;\n \n \tmove_cache_to_base_index(istate);\n+\tslog_tid = slog_start_timer(\"index\", \"do_write_index\");\n \tret = do_write_index(si->base, *temp, 1);\n+\tslog_stop_timer(slog_tid);\n \tif (ret)\n \t\treturn ret;\n \tret = adjust_shared_perm(get_tempfile_path(*temp));\n-- \n2.9.3\n\n"},{"id":"352487","messageId":"20180713165621.52017-15-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 14/25] structured-logging: add timer around preload_index","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:56:10Z","receivedAt":"2018-07-13T16:56:41Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nUse a SLOG timer to record the time spend in preload_index() and\nreport it in the \"cmd_exit\" event.\n\nSigned-off-by: Jeff Hostetler \n---\n preload-index.c | 6 ++++++\n 1 file changed, 6 insertions(+)\n\ndiff --git a/preload-index.c b/preload-index.c\nindex 4d08d44..572bb56 100644\n--- a/preload-index.c\n+++ b/preload-index.c\n@@ -116,8 +116,14 @@ static void preload_index(struct index_state *index,\n int read_index_preload(struct index_state *index,\n \t\t const struct pathspec *pathspec)\n {\n+\tint slog_tid;\n \tint retval = read_index(index);\n \n+\tslog_tid = slog_start_timer(\"index\", \"preload\");\n+\n \tpreload_index(index, pathspec);\n+\n+\tslog_stop_timer(slog_tid);\n+\n \treturn retval;\n }\n-- \n2.9.3\n\n"},{"id":"352489","messageId":"20180713165621.52017-17-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 16/25] structured-logging: add aux-data facility","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:56:12Z","receivedAt":"2018-07-13T16:56:42Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nAdd facility to add extra data to the structured logging data allowing\narbitrary key/value pair data to be added to the \"cmd_exit\" event.\n\nSigned-off-by: Jeff Hostetler \n---\n Documentation/config.txt | 6 +++\n structured-logging.c | 116 +++++++++++++++++++++++++++++++++++++++++++++++\n structured-logging.h | 21 +++++++++\n 3 files changed, 143 insertions(+)\n\ndiff --git a/Documentation/config.txt b/Documentation/config.txt\nindex 7817966..ca78d4c 100644\n--- a/Documentation/config.txt\n+++ b/Documentation/config.txt\n@@ -3195,6 +3195,12 @@ slog.timers::\n \tenabled. Defaults to off. Data for enabled timers is added to\n \tthe `cmd_exit` event.\n \n+slog.aux::\n+\t(EXPERIMENTAL) May be set to a boolean value or a list of\n+\tcomma separated tokens. Controls which categories of SLOG\n+\t\"aux\" data are enabled. Defaults to off. \"Aux\" data is added\n+\tto the `cmd_exit` event.\n+\n splitIndex.maxPercentChange::\n \tWhen the split index feature is used, this specifies the\n \tpercent of entries the split index can contain compared to the\ndiff --git a/structured-logging.c b/structured-logging.c\nindex 215138c..584f70a 100644\n--- a/structured-logging.c\n+++ b/structured-logging.c\n@@ -35,6 +35,19 @@ static struct timer_data_array my__timers;\n static void format_timers(struct json_writer *jw);\n static void free_timers(void);\n \n+struct aux_data {\n+\tchar *category;\n+\tstruct json_writer jw;\n+};\n+\n+struct aux_data_array {\n+\tstruct aux_data **array;\n+\tsize_t nr, alloc;\n+};\n+\n+static struct aux_data_array my__aux_data;\n+static void format_and_free_aux_data(struct json_writer *jw);\n+\n static uint64_t my__start_time;\n static uint64_t my__exit_time;\n static int my__is_config_loaded;\n@@ -62,6 +75,7 @@ struct category_filter\n \n static struct category_filter my__detail_categories;\n static struct category_filter my__timer_categories;\n+static struct category_filter my__aux_categories;\n \n static void set_want_categories(struct category_filter *cf, const char *value)\n {\n@@ -255,6 +269,12 @@ static void emit_exit_event(void)\n \t\t\tformat_timers(&jw);\n \t\t\tjw_end(&jw);\n \t\t}\n+\n+\t\tif (my__aux_data.nr) {\n+\t\t\tjw_object_inline_begin_object(&jw, \"aux\");\n+\t\t\tformat_and_free_aux_data(&jw);\n+\t\t\tjw_end(&jw);\n+\t\t}\n \t}\n \tjw_end(&jw);\n \n@@ -327,6 +347,12 @@ static int cfg_timers(const char *key, const char *value)\n \treturn 0;\n }\n \n+static int cfg_aux(const char *key, const char *value)\n+{\n+\tset_want_categories(&my__aux_categories, value);\n+\treturn 0;\n+}\n+\n int slog_default_config(const char *key, const char *value)\n {\n \tconst char *sub;\n@@ -349,6 +375,8 @@ int slog_default_config(const char *key, const char *value)\n \t\t\treturn cfg_detail(key, value);\n \t\tif (!strcmp(sub, \"timers\"))\n \t\t\treturn cfg_timers(key, value);\n+\t\tif (!strcmp(sub, \"aux\"))\n+\t\t\treturn cfg_aux(key, value);\n \t}\n \n \treturn 0;\n@@ -699,4 +727,92 @@ static void free_timers(void)\n \tmy__timers.alloc = 0;\n }\n \n+int slog_want_aux(const char *category)\n+{\n+\treturn want_category(&my__aux_categories, category);\n+}\n+\n+static struct aux_data *find_aux_data(const char *category)\n+{\n+\tstruct aux_data *ad;\n+\tint k;\n+\n+\tif (!slog_want_aux(category))\n+\t\treturn NULL;\n+\n+\tfor (k = 0; k < my__aux_data.nr; k++) {\n+\t\tad = my__aux_data.array[k];\n+\t\tif (!strcmp(category, ad->category))\n+\t\t\treturn ad;\n+\t}\n+\n+\tad = xcalloc(1, sizeof(struct aux_data));\n+\tad->category = xstrdup(category);\n+\n+\tjw_array_begin(&ad->jw, my__is_pretty);\n+\t/* leave per-category object unterminated for now */\n+\n+\tALLOC_GROW(my__aux_data.array, my__aux_data.nr + 1, my__aux_data.alloc);\n+\tmy__aux_data.array[my__aux_data.nr++] = ad;\n+\n+\treturn ad;\n+}\n+\n+#define add_to_aux(c, k, v, fn)\t\t\t\t\t\t\\\n+\tdo {\t\t\t\t\t\t\t\t\\\n+\t\tstruct aux_data *ad = find_aux_data((c));\t\t\\\n+\t\tif (ad) {\t\t\t\t\t\t\\\n+\t\t\tjw_array_inline_begin_array(&ad->jw);\t\t\\\n+\t\t\t{\t\t\t\t\t\t\\\n+\t\t\t\tjw_array_string(&ad->jw, (k));\t\t\\\n+\t\t\t\t(fn)(&ad->jw, (v));\t\t\t\\\n+\t\t\t}\t\t\t\t\t\t\\\n+\t\t\tjw_end(&ad->jw);\t\t\t\t\\\n+\t\t}\t\t\t\t\t\t\t\\\n+\t} while (0)\n+\n+void slog_aux_string(const char *category, const char *key, const char *value)\n+{\n+\tadd_to_aux(category, key, value, jw_array_string);\n+}\n+\n+void slog_aux_intmax(const char *category, const char *key, intmax_t value)\n+{\n+\tadd_to_aux(category, key, value, jw_array_intmax);\n+}\n+\n+void slog_aux_bool(const char *category, const char *key, int value)\n+{\n+\tadd_to_aux(category, key, value, jw_array_bool);\n+}\n+\n+void slog_aux_jw(const char *category, const char *key,\n+\t\t const struct json_writer *value)\n+{\n+\tadd_to_aux(category, key, value, jw_array_sub_jw);\n+}\n+\n+static void format_and_free_aux_data(struct json_writer *jw)\n+{\n+\tint k;\n+\n+\tfor (k = 0; k < my__aux_data.nr; k++) {\n+\t\tstruct aux_data *ad = my__aux_data.array[k];\n+\n+\t\t/* terminate per-category form */\n+\t\tjw_end(&ad->jw);\n+\n+\t\t/* insert per-category form into containing \"aux\" form */\n+\t\tjw_object_sub_jw(jw, ad->category, &ad->jw);\n+\n+\t\tjw_release(&ad->jw);\n+\t\tfree(ad->category);\n+\t\tfree(ad);\n+\t}\n+\n+\tFREE_AND_NULL(my__aux_data.array);\n+\tmy__aux_data.nr = 0;\n+\tmy__aux_data.alloc = 0;\n+}\n+\n #endif\ndiff --git a/structured-logging.h b/structured-logging.h\nindex a29aa6e..2272598 100644\n--- a/structured-logging.h\n+++ b/structured-logging.h\n@@ -25,6 +25,11 @@ typedef int (*slog_fn_main_t)(int, const char **);\n #define slog_emit_detail_event(category, label, data) do { } while (0)\n #define slog_start_timer(category, name) (SLOG_UNDEFINED_TIMER_ID)\n static inline void slog_stop_timer(int tid) { };\n+#define slog_want_aux(c) (0)\n+#define slog_aux_string(c, k, v) do { } while (0)\n+#define slog_aux_intmax(c, k, v) do { } while (0)\n+#define slog_aux_bool(c, k, v) do { } while (0)\n+#define slog_aux_jw(c, k, v) do { } while (0)\n \n #else\n \n@@ -126,5 +131,21 @@ int slog_start_timer(const char *category, const char *name);\n */\n void slog_stop_timer(int tid);\n \n+/*\n+ * Add arbitrary extra key/value data to the \"cmd_exit\" event.\n+ * These fields will appear under the \"aux\" object. This is\n+ * intended for \"interesting\" config values or repo stats, such\n+ * as the size of the index.\n+ *\n+ * These key/value pairs are written as an array-pair rather than\n+ * an object/value because the keys may be repeated.\n+ */\n+int slog_want_aux(const char *category);\n+void slog_aux_string(const char *category, const char *key, const char *value);\n+void slog_aux_intmax(const char *category, const char *key, intmax_t value);\n+void slog_aux_bool(const char *category, const char *key, int value);\n+void slog_aux_jw(const char *category, const char *key,\n+\t\t const struct json_writer *value);\n+\n #endif /* STRUCTURED_LOGGING */\n #endif /* STRUCTURED_LOGGING_H */\n-- \n2.9.3\n\n"},{"id":"352490","messageId":"20180713165621.52017-18-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 17/25] structured-logging: add aux-data for index size","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:56:13Z","receivedAt":"2018-07-13T16:56:42Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nTeach do_read_index() and do_write_index() to record the size of the index\nin aux-data. This will be reported in the \"cmd_exit\" event.\n\nSigned-off-by: Jeff Hostetler \n---\n read-cache.c | 4 ++++\n 1 file changed, 4 insertions(+)\n\ndiff --git a/read-cache.c b/read-cache.c\nindex 7fe66b5..b6e2cfa 100644\n--- a/read-cache.c\n+++ b/read-cache.c\n@@ -1916,6 +1916,8 @@ int read_index_from(struct index_state *istate, const char *path,\n \tslog_stop_timer(slog_tid);\n \ttrace_performance_since(start, \"read cache %s\", path);\n \n+\tslog_aux_intmax(\"index\", \"cache_nr\", istate->cache_nr);\n+\n \tsplit_index = istate->split_index;\n \tif (!split_index || is_null_oid(&split_index->base_oid)) {\n \t\tpost_read_index_from(istate);\n@@ -1937,6 +1939,8 @@ int read_index_from(struct index_state *istate, const char *path,\n \t\t base_oid_hex, base_path,\n \t\t oid_to_hex(&split_index->base->oid));\n \n+\tslog_aux_intmax(\"index\", \"split_index_cache_nr\", split_index->base->cache_nr);\n+\n \tfreshen_shared_index(base_path, 0);\n \tmerge_base_index(istate);\n \tpost_read_index_from(istate);\n-- \n2.9.3\n\n"},{"id":"352491","messageId":"20180713165621.52017-20-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 19/25] structured-logging: t0420 tests for aux-data","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:56:15Z","receivedAt":"2018-07-13T16:56:43Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nSigned-off-by: Jeff Hostetler \n---\n t/t0420-structured-logging.sh | 33 +++++++++++++++++++++++++++++++++\n 1 file changed, 33 insertions(+)\n\ndiff --git a/t/t0420-structured-logging.sh b/t/t0420-structured-logging.sh\nindex 37c7e83..2e06cd7 100755\n--- a/t/t0420-structured-logging.sh\n+++ b/t/t0420-structured-logging.sh\n@@ -188,4 +188,37 @@ test_expect_success PERLJSON 'turn on index timers only' '\n \ttest_expect_code 1 grep \"row\\[0\\]\\.timers\\.status\\.untracked\\.total_us\" .git/info/sparse-checkout &&\n+\tgit config --local core.sparsecheckout true &&\n+\tgit config --local slog.aux foo,index,bar &&\n+\trm -f \"$LOGFILE\" &&\n+\n+\tgit checkout HEAD &&\n+\n+\tgrep -f key_cmd_exit \"$LOGFILE\" >event_exit &&\n+\n+\tperl \"$TEST_DIRECTORY\"/t0420/parse_json.perl parsed_exit &&\n+\n+\tgrep \"row\\[0\\]\\.version\\.slog 0\" ][0] cache_nr\n+\t# row[0].aux.index[][1] 1\n+\t# row[0].aux.index[][0] sparse_checkout_count\n+\t# row[0].aux.index[][1] 1\n+\t#\n+\t# But do not assume values for and (in case the sorting changes\n+\t# or other \"aux\" fields are added later).\n+\n+\tgrep \"row\\[0\\]\\.aux\\.index\\[.*\\]\\[0\\] cache_nr\" \n\nTeach unpack_trees() to record the number of entries in the sparse-checkout\nfile in the aux-data. This will be reported in the \"cmd_exit\" event.\n\nSigned-off-by: Jeff Hostetler \n---\n unpack-trees.c | 4 +++-\n 1 file changed, 3 insertions(+), 1 deletion(-)\n\ndiff --git a/unpack-trees.c b/unpack-trees.c\nindex 3a85a02..71b1b93 100644\n--- a/unpack-trees.c\n+++ b/unpack-trees.c\n@@ -1285,8 +1285,10 @@ int unpack_trees(unsigned len, struct tree_desc *t, struct unpack_trees_options\n \t\tchar *sparse = git_pathdup(\"info/sparse-checkout\");\n \t\tif (add_excludes_from_file_to_list(sparse, \"\", 0, &el, NULL) < 0)\n \t\t\to->skip_sparse_checkout = 1;\n-\t\telse\n+\t\telse {\n \t\t\to->el = ⪙\n+\t\t\tslog_aux_intmax(\"index\", \"sparse_checkout_count\", el.nr);\n+\t\t}\n \t\tfree(sparse);\n \t}\n \n-- \n2.9.3\n\n"},{"id":"352493","messageId":"20180713165621.52017-21-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 20/25] structured-logging: add structured logging to remote-curl","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:56:16Z","receivedAt":"2018-07-13T16:56:44Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nremote-curl is not a builtin command and therefore, does not inherit\nthe common cmd_main() startup in git.c\n\nWrap cmd_main() with slog_cmd_main() in remote-curl to initialize\nlogging.\n\nAdd slog timers around push, fetch, and list verbs.\n\nSigned-off-by: Jeff Hostetler \n---\n remote-curl.c | 16 +++++++++++++++-\n 1 file changed, 15 insertions(+), 1 deletion(-)\n\ndiff --git a/remote-curl.c b/remote-curl.c\nindex 99b0bed..ed910f8 100644\n--- a/remote-curl.c\n+++ b/remote-curl.c\n@@ -1322,8 +1322,9 @@ static int stateless_connect(const char *service_name)\n \treturn 0;\n }\n \n-int cmd_main(int argc, const char **argv)\n+static int real_cmd_main(int argc, const char **argv)\n {\n+\tint slog_tid;\n \tstruct strbuf buf = STRBUF_INIT;\n \tint nongit;\n \n@@ -1333,6 +1334,8 @@ int cmd_main(int argc, const char **argv)\n \t\treturn 1;\n \t}\n \n+\tslog_set_command_name(\"remote-curl\");\n+\n \toptions.verbosity = 1;\n \toptions.progress = !!isatty(2);\n \toptions.thin = 1;\n@@ -1362,14 +1365,20 @@ int cmd_main(int argc, const char **argv)\n \t\tif (starts_with(buf.buf, \"fetch \")) {\n \t\t\tif (nongit)\n \t\t\t\tdie(\"remote-curl: fetch attempted without a local repo\");\n+\t\t\tslog_tid = slog_start_timer(\"curl\", \"fetch\");\n \t\t\tparse_fetch(&buf);\n+\t\t\tslog_stop_timer(slog_tid);\n \n \t\t} else if (!strcmp(buf.buf, \"list\") || starts_with(buf.buf, \"list \")) {\n \t\t\tint for_push = !!strstr(buf.buf + 4, \"for-push\");\n+\t\t\tslog_tid = slog_start_timer(\"curl\", \"list\");\n \t\t\toutput_refs(get_refs(for_push));\n+\t\t\tslog_stop_timer(slog_tid);\n \n \t\t} else if (starts_with(buf.buf, \"push \")) {\n+\t\t\tslog_tid = slog_start_timer(\"curl\", \"push\");\n \t\t\tparse_push(&buf);\n+\t\t\tslog_stop_timer(slog_tid);\n \n \t\t} else if (skip_prefix(buf.buf, \"option \", &arg)) {\n \t\t\tchar *value = strchr(arg, ' ');\n@@ -1411,3 +1420,8 @@ int cmd_main(int argc, const char **argv)\n \n \treturn 0;\n }\n+\n+int cmd_main(int argc, const char **argv)\n+{\n+\treturn slog_wrap_main(real_cmd_main, argc, argv);\n+}\n-- \n2.9.3\n\n"},{"id":"352494","messageId":"20180713165621.52017-24-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 23/25] structured-logging: t0420 tests for child process detail events","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:56:19Z","receivedAt":"2018-07-13T16:56:46Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nSigned-off-by: Jeff Hostetler \n---\n t/t0420-structured-logging.sh | 39 +++++++++++++++++++++++++++++++++++++++\n 1 file changed, 39 insertions(+)\n\ndiff --git a/t/t0420-structured-logging.sh b/t/t0420-structured-logging.sh\nindex 2e06cd7..4ac404d 100755\n--- a/t/t0420-structured-logging.sh\n+++ b/t/t0420-structured-logging.sh\n@@ -26,6 +26,9 @@ test_expect_success 'setup' '\n \tcat >key_exit_code_129 <<-\\EOF &&\n \t\"exit_code\":129\n \tEOF\n+\tcat >key_detail <<-\\EOF &&\n+\t\"event\":\"detail\"\n+\tEOF\n \tgit config --local slog.pretty false &&\n \tgit config --local slog.path \"$LOGFILE\"\n '\n@@ -221,4 +224,40 @@ test_expect_success PERLJSON 'turn on aux-data, verify a few fields' '\n \tgrep \"row\\[0\\]\\.aux\\.index\\[.*\\]\\[0\\] sparse_checkout_count\" event_exit &&\n+\tgrep -f key_detail \"$LOGFILE\" >event_detail &&\n+\n+\tperl \"$TEST_DIRECTORY\"/t0420/parse_json.perl parsed_exit &&\n+\tperl \"$TEST_DIRECTORY\"/t0420/parse_json.perl parsed_detail &&\n+\n+\tgrep \"row\\[0\\]\\.event cmd_exit\" \n\nTeach git to emit \"detail\" events with category \"child\" before a child\nprocess is started and after it finishes. These events can be used to\ninfer time spent by git waiting for child processes to complete.\n\nThese events are controlled by the slog.detail config setting. Set to\ntrue or add the token \"child\" to it.\n\nSigned-off-by: Jeff Hostetler \n---\n run-command.c | 14 ++++-\n run-command.h | 1 +\n structured-logging.c | 154 ++++++++++++++++++++++++++++++++++++++++++++++++++-\n structured-logging.h | 15 +++++\n 4 files changed, 181 insertions(+), 3 deletions(-)\n\ndiff --git a/run-command.c b/run-command.c\nindex 84b883c..30fb4c5 100644\n--- a/run-command.c\n+++ b/run-command.c\n@@ -710,6 +710,8 @@ int start_command(struct child_process *cmd)\n \n \tfflush(NULL);\n \n+\tcmd->slog_child_id = slog_child_starting(cmd);\n+\n #ifndef GIT_WINDOWS_NATIVE\n {\n \tint notify_pipe[2];\n@@ -923,6 +925,9 @@ int start_command(struct child_process *cmd)\n \t\t\tclose_pair(fderr);\n \t\telse if (cmd->err)\n \t\t\tclose(cmd->err);\n+\n+\t\tslog_child_ended(cmd->slog_child_id, cmd->pid, failed_errno);\n+\n \t\tchild_process_clear(cmd);\n \t\terrno = failed_errno;\n \t\treturn -1;\n@@ -949,13 +954,20 @@ int start_command(struct child_process *cmd)\n int finish_command(struct child_process *cmd)\n {\n \tint ret = wait_or_whine(cmd->pid, cmd->argv[0], 0);\n+\n+\tslog_child_ended(cmd->slog_child_id, cmd->pid, ret);\n+\n \tchild_process_clear(cmd);\n \treturn ret;\n }\n \n int finish_command_in_signal(struct child_process *cmd)\n {\n-\treturn wait_or_whine(cmd->pid, cmd->argv[0], 1);\n+\tint ret = wait_or_whine(cmd->pid, cmd->argv[0], 1);\n+\n+\tslog_child_ended(cmd->slog_child_id, cmd->pid, ret);\n+\n+\treturn ret;\n }\n \n \ndiff --git a/run-command.h b/run-command.h\nindex 3932420..89c89cf 100644\n--- a/run-command.h\n+++ b/run-command.h\n@@ -12,6 +12,7 @@ struct child_process {\n \tstruct argv_array args;\n \tstruct argv_array env_array;\n \tpid_t pid;\n+\tint slog_child_id;\n \t/*\n \t * Using .in, .out, .err:\n \t * - Specify 0 for no redirections (child inherits stdin, stdout,\ndiff --git a/structured-logging.c b/structured-logging.c\nindex 584f70a..dbe60b7 100644\n--- a/structured-logging.c\n+++ b/structured-logging.c\n@@ -4,6 +4,7 @@\n #include \"json-writer.h\"\n #include \"sigchain.h\"\n #include \"argv-array.h\"\n+#include \"run-command.h\"\n \n #if !defined(STRUCTURED_LOGGING)\n /*\n@@ -48,6 +49,23 @@ struct aux_data_array {\n static struct aux_data_array my__aux_data;\n static void format_and_free_aux_data(struct json_writer *jw);\n \n+struct child_data {\n+\tuint64_t start_ns;\n+\tuint64_t end_ns;\n+\tstruct json_writer jw_argv;\n+\tunsigned int is_running:1;\n+\tunsigned int is_git_cmd:1;\n+\tunsigned int use_shell:1;\n+};\n+\n+struct child_data_array {\n+\tstruct child_data **array;\n+\tsize_t nr, alloc;\n+};\n+\n+static struct child_data_array my__child_data;\n+static void free_children(void);\n+\n static uint64_t my__start_time;\n static uint64_t my__exit_time;\n static int my__is_config_loaded;\n@@ -283,10 +301,11 @@ static void emit_exit_event(void)\n }\n \n static void emit_detail_event(const char *category, const char *label,\n+\t\t\t uint64_t clock_ns,\n \t\t\t const struct json_writer *data)\n {\n \tstruct json_writer jw = JSON_WRITER_INIT;\n-\tuint64_t clock_us = getnanotime() / 1000;\n+\tuint64_t clock_us = clock_ns / 1000;\n \n \t/* build \"detail\" event */\n \tjw_object_begin(&jw, my__is_pretty);\n@@ -435,6 +454,7 @@ static void do_final_steps(int in_signal)\n \tjw_release(&my__errors);\n \tstrbuf_release(&my__session_id);\n \tfree_timers();\n+\tfree_children();\n }\n \n static void slog_atexit(void)\n@@ -580,7 +600,7 @@ void slog_emit_detail_event(const char *category, const char *label,\n \t\tBUG(\"unterminated slog.detail data: '%s' '%s' '%s'\",\n \t\t category, label, data->json.buf);\n \n-\temit_detail_event(category, label, data);\n+\temit_detail_event(category, label, getnanotime(), data);\n }\n \n int slog_start_timer(const char *category, const char *name)\n@@ -815,4 +835,134 @@ static void format_and_free_aux_data(struct json_writer *jw)\n \tmy__aux_data.alloc = 0;\n }\n \n+static struct child_data *alloc_child_data(const struct child_process *cmd)\n+{\n+\tstruct child_data *cd = xcalloc(1, sizeof(struct child_data));\n+\n+\tcd->start_ns = getnanotime();\n+\tcd->is_running = 1;\n+\tcd->is_git_cmd = cmd->git_cmd;\n+\tcd->use_shell = cmd->use_shell;\n+\n+\tjw_init(&cd->jw_argv);\n+\n+\tjw_array_begin(&cd->jw_argv, my__is_pretty);\n+\t{\n+\t\tjw_array_argv(&cd->jw_argv, cmd->argv);\n+\t}\n+\tjw_end(&cd->jw_argv);\n+\n+\treturn cd;\n+}\n+\n+static int insert_child_data(struct child_data *cd)\n+{\n+\tint child_id = my__child_data.nr;\n+\n+\tALLOC_GROW(my__child_data.array, my__child_data.nr + 1,\n+\t\t my__child_data.alloc);\n+\tmy__child_data.array[my__child_data.nr++] = cd;\n+\n+\treturn child_id;\n+}\n+\n+int slog_child_starting(const struct child_process *cmd)\n+{\n+\tstruct child_data *cd;\n+\tint child_id;\n+\n+\tif (!slog_is_enabled())\n+\t\treturn SLOG_UNDEFINED_CHILD_ID;\n+\n+\t/*\n+\t * If we have not yet written a cmd_start event (and even if\n+\t * we do not emit this child_start event), force the cmd_start\n+\t * event now so that it appears in the log before any events\n+\t * that the child process itself emits.\n+\t */\n+\tif (!my__wrote_start_event)\n+\t\temit_start_event();\n+\n+\tcd = alloc_child_data(cmd);\n+\tchild_id = insert_child_data(cd);\n+\n+\t/* build data portion for a \"detail\" event */\n+\tif (slog_want_detail_event(\"child\")) {\n+\t\tstruct json_writer jw_data = JSON_WRITER_INIT;\n+\n+\t\tjw_object_begin(&jw_data, my__is_pretty);\n+\t\t{\n+\t\t\tjw_object_intmax(&jw_data, \"child_id\", child_id);\n+\t\t\tjw_object_bool(&jw_data, \"git_cmd\", cd->is_git_cmd);\n+\t\t\tjw_object_bool(&jw_data, \"use_shell\", cd->use_shell);\n+\t\t\tjw_object_sub_jw(&jw_data, \"child_argv\", &cd->jw_argv);\n+\t\t}\n+\t\tjw_end(&jw_data);\n+\n+\t\temit_detail_event(\"child\", \"child_starting\", cd->start_ns,\n+\t\t\t\t &jw_data);\n+\t\tjw_release(&jw_data);\n+\t}\n+\n+\treturn child_id;\n+}\n+\n+void slog_child_ended(int child_id, int child_pid, int child_exit_code)\n+{\n+\tstruct child_data *cd;\n+\n+\tif (!slog_is_enabled())\n+\t\treturn;\n+\tif (child_id == SLOG_UNDEFINED_CHILD_ID)\n+\t\treturn;\n+\tif (child_id >= my__child_data.nr || child_id < 0)\n+\t\tBUG(\"Invalid slog.child id '%d'\", child_id);\n+\n+\tcd = my__child_data.array[child_id];\n+\tif (!cd->is_running)\n+\t\tBUG(\"slog.child '%d' already stopped\", child_id);\n+\n+\tcd->end_ns = getnanotime();\n+\tcd->is_running = 0;\n+\n+\t/* build data portion for a \"detail\" event */\n+\tif (slog_want_detail_event(\"child\")) {\n+\t\tstruct json_writer jw_data = JSON_WRITER_INIT;\n+\n+\t\tjw_object_begin(&jw_data, my__is_pretty);\n+\t\t{\n+\t\t\tjw_object_intmax(&jw_data, \"child_id\", child_id);\n+\t\t\tjw_object_bool(&jw_data, \"git_cmd\", cd->is_git_cmd);\n+\t\t\tjw_object_bool(&jw_data, \"use_shell\", cd->use_shell);\n+\t\t\tjw_object_sub_jw(&jw_data, \"child_argv\", &cd->jw_argv);\n+\n+\t\t\tjw_object_intmax(&jw_data, \"child_pid\", child_pid);\n+\t\t\tjw_object_intmax(&jw_data, \"child_exit_code\",\n+\t\t\t\t\t child_exit_code);\n+\t\t\tjw_object_intmax(&jw_data, \"child_elapsed_us\",\n+\t\t\t\t\t (cd->end_ns - cd->start_ns) / 1000);\n+\t\t}\n+\t\tjw_end(&jw_data);\n+\n+\t\temit_detail_event(\"child\", \"child_ended\", cd->end_ns, &jw_data);\n+\t\tjw_release(&jw_data);\n+\t}\n+}\n+\n+static void free_children(void)\n+{\n+\tint k;\n+\n+\tfor (k = 0; k < my__child_data.nr; k++) {\n+\t\tstruct child_data *cd = my__child_data.array[k];\n+\n+\t\tjw_release(&cd->jw_argv);\n+\t\tfree(cd);\n+\t}\n+\n+\tFREE_AND_NULL(my__child_data.array);\n+\tmy__child_data.nr = 0;\n+\tmy__child_data.alloc = 0;\n+}\n+\n #endif\ndiff --git a/structured-logging.h b/structured-logging.h\nindex 2272598..7c98d33 100644\n--- a/structured-logging.h\n+++ b/structured-logging.h\n@@ -2,10 +2,12 @@\n #define STRUCTURED_LOGGING_H\n \n struct json_writer;\n+struct child_process;\n \n typedef int (*slog_fn_main_t)(int, const char **);\n \n #define SLOG_UNDEFINED_TIMER_ID (-1)\n+#define SLOG_UNDEFINED_CHILD_ID (-1)\n \n #if !defined(STRUCTURED_LOGGING)\n /*\n@@ -30,6 +32,8 @@ static inline void slog_stop_timer(int tid) { };\n #define slog_aux_intmax(c, k, v) do { } while (0)\n #define slog_aux_bool(c, k, v) do { } while (0)\n #define slog_aux_jw(c, k, v) do { } while (0)\n+#define slog_child_starting(cmd) (SLOG_UNDEFINED_CHILD_ID)\n+#define slog_child_ended(i, p, ec) do { } while (0)\n \n #else\n \n@@ -147,5 +151,16 @@ void slog_aux_bool(const char *category, const char *key, int value);\n void slog_aux_jw(const char *category, const char *key,\n \t\t const struct json_writer *value);\n \n+/*\n+ * Emit a detail event of category \"child\" and label \"child_starting\"\n+ * or \"child_ending\" with information about the child process. Note\n+ * that this is in addition to any events that the child process itself\n+ * generates.\n+ *\n+ * Set \"slog.detail\" to true or contain \"child\" to get these events.\n+ */\n+int slog_child_starting(const struct child_process *cmd);\n+void slog_child_ended(int child_id, int child_pid, int child_exit_code);\n+\n #endif /* STRUCTURED_LOGGING */\n #endif /* STRUCTURED_LOGGING_H */\n-- \n2.9.3\n\n"},{"id":"352496","messageId":"20180713165621.52017-26-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 25/25] structured-logging: add config data facility","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:56:21Z","receivedAt":"2018-07-13T16:56:47Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nAdd \"config\" section to \"cmd_exit\" event to record important\nconfiguration settings in the log.\n\nAdd the value of \"slog.detail\", \"slog.timers\", and \"slog.aux\" config\nsettings to the log. These values control the filtering of the log.\nKnowing the filter settings can help post-processors reason about\nthe contents of the log.\n\nSigned-off-by: Jeff Hostetler \n---\n structured-logging.c | 132 +++++++++++++++++++++++++++++++++++++++++++++++++++\n structured-logging.h | 13 +++++\n 2 files changed, 145 insertions(+)\n\ndiff --git a/structured-logging.c b/structured-logging.c\nindex 2571e79..0e3f79e 100644\n--- a/structured-logging.c\n+++ b/structured-logging.c\n@@ -83,6 +83,20 @@ struct child_data_array {\n static struct child_data_array my__child_data;\n static void free_children(void);\n \n+struct config_data {\n+\tchar *group;\n+\tstruct json_writer jw;\n+};\n+\n+struct config_data_array {\n+\tstruct config_data **array;\n+\tsize_t nr, alloc;\n+};\n+\n+static struct config_data_array my__config_data;\n+static void format_config_data(struct json_writer *jw);\n+static void free_config_data(void);\n+\n static uint64_t my__start_time;\n static uint64_t my__exit_time;\n static int my__is_config_loaded;\n@@ -132,6 +146,15 @@ static int want_category(const struct category_filter *cf, const char *category)\n \treturn !!strstr(cf->categories, category);\n }\n \n+static void set_config_data_from_category(const struct category_filter *cf,\n+\t\t\t\t\t const char *key)\n+{\n+\tif (cf->want == 0 || cf->want == 1)\n+\t\tslog_set_config_data_intmax(key, cf->want);\n+\telse\n+\t\tslog_set_config_data_string(key, cf->categories);\n+}\n+\n /*\n * Compute a new session id for the current process. Build string\n * with the start time and PID of the current process and append\n@@ -249,6 +272,18 @@ static void emit_exit_event(void)\n \tstruct json_writer jw = JSON_WRITER_INIT;\n \tuint64_t atexit_time = getnanotime() / 1000;\n \n+\t/*\n+\t * Copy important (and non-obvious) config settings into the\n+\t * \"config\" section of the \"cmd_exit\" event. The values of\n+\t * \"slog.detail\", \"slog.timers\", and \"slog.aux\" are used in\n+\t * category want filtering, so post-processors should know the\n+\t * filter settings so that they can tell if an event is missing\n+\t * because of filtering or an error.\n+\t */\n+\tset_config_data_from_category(&my__detail_categories, \"slog.detail\");\n+\tset_config_data_from_category(&my__timer_categories, \"slog.timers\");\n+\tset_config_data_from_category(&my__aux_categories, \"slog.aux\");\n+\n \t/* close unterminated forms */\n \tif (my__errors.json.len)\n \t\tjw_end(&my__errors);\n@@ -299,6 +334,12 @@ static void emit_exit_event(void)\n \t\t}\n \t\tjw_end(&jw);\n \n+\t\tif (my__config_data.nr) {\n+\t\t\tjw_object_inline_begin_object(&jw, \"config\");\n+\t\t\tformat_config_data(&jw);\n+\t\t\tjw_end(&jw);\n+\t\t}\n+\n \t\tif (my__timers.nr) {\n \t\t\tjw_object_inline_begin_object(&jw, \"timers\");\n \t\t\tformat_timers(&jw);\n@@ -479,6 +520,7 @@ static void do_final_steps(int in_signal)\n \tfree_child_summary_data();\n \tfree_timers();\n \tfree_children();\n+\tfree_config_data();\n }\n \n static void slog_atexit(void)\n@@ -1084,4 +1126,94 @@ static void free_children(void)\n \tmy__child_data.alloc = 0;\n }\n \n+/*\n+ * Split into . (for example \"slog.path\" into \"slog\" and \"path\")\n+ * Find or insert in config_data_array[].\n+ *\n+ * Return config_data_arary[].\n+ */\n+static struct config_data *find_config_data(const char *key, const char **sub_key)\n+{\n+\tstruct config_data *cd;\n+\tchar *dot;\n+\tsize_t group_len;\n+\tint k;\n+\n+\tdot = strchr(key, '.');\n+\tif (!dot)\n+\t\treturn NULL;\n+\n+\t*sub_key = dot + 1;\n+\n+\tgroup_len = dot - key;\n+\n+\tfor (k = 0; k < my__config_data.nr; k++) {\n+\t\tcd = my__config_data.array[k];\n+\t\tif (!strncmp(key, cd->group, group_len))\n+\t\t\treturn cd;\n+\t}\n+\n+\tcd = xcalloc(1, sizeof(struct config_data));\n+\tcd->group = xstrndup(key, group_len);\n+\n+\tjw_object_begin(&cd->jw, my__is_pretty);\n+\t/* leave per-group object unterminated for now */\n+\n+\tALLOC_GROW(my__config_data.array, my__config_data.nr + 1,\n+\t\t my__config_data.alloc);\n+\tmy__config_data.array[my__config_data.nr++] = cd;\n+\n+\treturn cd;\n+}\n+\n+void slog_set_config_data_string(const char *key, const char *value)\n+{\n+\tconst char *sub_key;\n+\tstruct config_data *cd = find_config_data(key, &sub_key);\n+\n+\tif (cd)\n+\t\tjw_object_string(&cd->jw, sub_key, value);\n+}\n+\n+void slog_set_config_data_intmax(const char *key, intmax_t value)\n+{\n+\tconst char *sub_key;\n+\tstruct config_data *cd = find_config_data(key, &sub_key);\n+\n+\tif (cd)\n+\t\tjw_object_intmax(&cd->jw, sub_key, value);\n+}\n+\n+static void format_config_data(struct json_writer *jw)\n+{\n+\tint k;\n+\n+\tfor (k = 0; k < my__config_data.nr; k++) {\n+\t\tstruct config_data *cd = my__config_data.array[k];\n+\n+\t\t/* termminate per-group form */\n+\t\tjw_end(&cd->jw);\n+\n+\t\t/* insert per-category form into containing \"config\" form */\n+\t\tjw_object_sub_jw(jw, cd->group, &cd->jw);\n+\t}\n+}\n+\n+static void free_config_data(void)\n+{\n+\tint k;\n+\n+\tfor (k = 0; k < my__config_data.nr; k++) {\n+\t\tstruct config_data *cd = my__config_data.array[k];\n+\n+\t\tjw_release(&cd->jw);\n+\t\tfree(cd->group);\n+\t\tfree(cd);\n+\t}\n+\n+\tFREE_AND_NULL(my__config_data.array);\n+\tmy__config_data.nr = 0;\n+\tmy__config_data.alloc = 0;\n+}\n+\n #endif\ndiff --git a/structured-logging.h b/structured-logging.h\nindex 7c98d33..2c90267 100644\n--- a/structured-logging.h\n+++ b/structured-logging.h\n@@ -34,6 +34,8 @@ static inline void slog_stop_timer(int tid) { };\n #define slog_aux_jw(c, k, v) do { } while (0)\n #define slog_child_starting(cmd) (SLOG_UNDEFINED_CHILD_ID)\n #define slog_child_ended(i, p, ec) do { } while (0)\n+#define slog_set_config_data_string(k, v) do { } while (0)\n+#define slog_set_config_data_intmax(k, v) do { } while (0)\n \n #else\n \n@@ -162,5 +164,16 @@ void slog_aux_jw(const char *category, const char *key,\n int slog_child_starting(const struct child_process *cmd);\n void slog_child_ended(int child_id, int child_pid, int child_exit_code);\n \n+/*\n+ * Add an important config key/value pair to the \"cmd_event\". Keys\n+ * are assumed to be of the form ., such as \"slog.path\".\n+ * The pair will appear under the \"config\" object in the resulting JSON\n+ * as \"config..:\".\n+ *\n+ * This should only be used for important config settings.\n+ */\n+void slog_set_config_data_string(const char *key, const char *value);\n+void slog_set_config_data_intmax(const char *key, intmax_t value);\n+\n #endif /* STRUCTURED_LOGGING */\n #endif /* STRUCTURED_LOGGING_H */\n-- \n2.9.3\n\n"},{"id":"352497","messageId":"20180713165621.52017-23-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 22/25] structured-logging: add child process classification","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:56:18Z","receivedAt":"2018-07-13T16:56:49Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nTeach git to classify child processes as \"editor\", \"pager\", \"subprocess\",\n\"alias\", \"shell\", or \"other\".\n\nAdd the child process classification to the child detail events.\n\nMark child processes of class \"editor\" or \"pager\" as interactive in the\nchild detail event.\n\nAdd child summary to cmd_exit event grouping child process by class.\n\nSigned-off-by: Jeff Hostetler \n---\n editor.c | 1 +\n git.c | 2 +\n pager.c | 1 +\n run-command.h | 1 +\n structured-logging.c | 119 +++++++++++++++++++++++++++++++++++++++++++++++++++\n sub-process.c | 1 +\n 6 files changed, 125 insertions(+)\n\ndiff --git a/editor.c b/editor.c\nindex 9a9b4e1..6f5ccf3 100644\n--- a/editor.c\n+++ b/editor.c\n@@ -66,6 +66,7 @@ int launch_editor(const char *path, struct strbuf *buffer, const char *const *en\n \t\tp.argv = args;\n \t\tp.env = env;\n \t\tp.use_shell = 1;\n+\t\tp.slog_child_class = \"editor\";\n \t\tif (start_command(&p) < 0)\n \t\t\treturn error(\"unable to start editor '%s'\", editor);\n \ndiff --git a/git.c b/git.c\nindex 024a40d..f1cb29e 100644\n--- a/git.c\n+++ b/git.c\n@@ -328,6 +328,7 @@ static int handle_alias(int *argcp, const char ***argv)\n \t\t\tcommit_pager_choice();\n \n \t\t\tchild.use_shell = 1;\n+\t\t\tchild.slog_child_class = \"alias\";\n \t\t\targv_array_push(&child.args, alias_string + 1);\n \t\t\targv_array_pushv(&child.args, (*argv) + 1);\n \n@@ -651,6 +652,7 @@ static void execv_dashed_external(const char **argv)\n \tcmd.clean_on_exit = 1;\n \tcmd.wait_after_clean = 1;\n \tcmd.silent_exec_failure = 1;\n+\tcmd.slog_child_class = \"alias\";\n \n \ttrace_argv_printf(cmd.args.argv, \"trace: exec:\");\n \ndiff --git a/pager.c b/pager.c\nindex a768797..5939077 100644\n--- a/pager.c\n+++ b/pager.c\n@@ -100,6 +100,7 @@ void prepare_pager_args(struct child_process *pager_process, const char *pager)\n \targv_array_push(&pager_process->args, pager);\n \tpager_process->use_shell = 1;\n \tsetup_pager_env(&pager_process->env_array);\n+\tpager_process->slog_child_class = \"pager\";\n }\n \n void setup_pager(void)\ndiff --git a/run-command.h b/run-command.h\nindex 89c89cf..8c99bd1 100644\n--- a/run-command.h\n+++ b/run-command.h\n@@ -13,6 +13,7 @@ struct child_process {\n \tstruct argv_array env_array;\n \tpid_t pid;\n \tint slog_child_id;\n+\tconst char *slog_child_class;\n \t/*\n \t * Using .in, .out, .err:\n \t * - Specify 0 for no redirections (child inherits stdin, stdout,\ndiff --git a/structured-logging.c b/structured-logging.c\nindex dbe60b7..2571e79 100644\n--- a/structured-logging.c\n+++ b/structured-logging.c\n@@ -49,13 +49,30 @@ struct aux_data_array {\n static struct aux_data_array my__aux_data;\n static void format_and_free_aux_data(struct json_writer *jw);\n \n+struct child_summary_data {\n+\tchar *child_class;\n+\tuint64_t total_ns;\n+\tint count;\n+};\n+\n+struct child_summary_data_array {\n+\tstruct child_summary_data **array;\n+\tsize_t nr, alloc;\n+};\n+\n+static struct child_summary_data_array my__child_summary_data;\n+static void format_child_summary_data(struct json_writer *jw);\n+static void free_child_summary_data(void);\n+\n struct child_data {\n \tuint64_t start_ns;\n \tuint64_t end_ns;\n \tstruct json_writer jw_argv;\n+\tchar *child_class;\n \tunsigned int is_running:1;\n \tunsigned int is_git_cmd:1;\n \tunsigned int use_shell:1;\n+\tunsigned int is_interactive:1;\n };\n \n struct child_data_array {\n@@ -293,6 +310,12 @@ static void emit_exit_event(void)\n \t\t\tformat_and_free_aux_data(&jw);\n \t\t\tjw_end(&jw);\n \t\t}\n+\n+\t\tif (my__child_summary_data.nr) {\n+\t\t\tjw_object_inline_begin_object(&jw, \"child_summary\");\n+\t\t\tformat_child_summary_data(&jw);\n+\t\t\tjw_end(&jw);\n+\t\t}\n \t}\n \tjw_end(&jw);\n \n@@ -453,6 +476,7 @@ static void do_final_steps(int in_signal)\n \targv_array_clear(&my__argv);\n \tjw_release(&my__errors);\n \tstrbuf_release(&my__session_id);\n+\tfree_child_summary_data();\n \tfree_timers();\n \tfree_children();\n }\n@@ -835,6 +859,85 @@ static void format_and_free_aux_data(struct json_writer *jw)\n \tmy__aux_data.alloc = 0;\n }\n \n+static struct child_summary_data *find_child_summary_data(\n+\tconst struct child_data *cd)\n+{\n+\tstruct child_summary_data *csd;\n+\tchar *child_class;\n+\tint k;\n+\n+\tchild_class = cd->child_class;\n+\tif (!child_class || !*child_class) {\n+\t\tif (cd->use_shell)\n+\t\t\tchild_class = \"shell\";\n+\t\tchild_class = \"other\";\n+\t}\n+\n+\tfor (k = 0; k < my__child_summary_data.nr; k++) {\n+\t\tcsd = my__child_summary_data.array[k];\n+\t\tif (!strcmp(child_class, csd->child_class))\n+\t\t\treturn csd;\n+\t}\n+\n+\tcsd = xcalloc(1, sizeof(struct child_summary_data));\n+\tcsd->child_class = xstrdup(child_class);\n+\n+\tALLOC_GROW(my__child_summary_data.array, my__child_summary_data.nr + 1,\n+\t\t my__child_summary_data.alloc);\n+\tmy__child_summary_data.array[my__child_summary_data.nr++] = csd;\n+\n+\treturn csd;\n+}\n+\n+static void add_child_to_summary_data(const struct child_data *cd)\n+{\n+\tstruct child_summary_data *csd = find_child_summary_data(cd);\n+\n+\tcsd->total_ns += cd->end_ns - cd->start_ns;\n+\tcsd->count++;\n+}\n+\n+static void format_child_summary_data(struct json_writer *jw)\n+{\n+\tint k;\n+\n+\tfor (k = 0; k < my__child_summary_data.nr; k++) {\n+\t\tstruct child_summary_data *csd = my__child_summary_data.array[k];\n+\n+\t\tjw_object_inline_begin_object(jw, csd->child_class);\n+\t\t{\n+\t\t\tjw_object_intmax(jw, \"total_us\", csd->total_ns / 1000);\n+\t\t\tjw_object_intmax(jw, \"count\", csd->count);\n+\t\t}\n+\t\tjw_end(jw);\n+\t}\n+}\n+\n+static void free_child_summary_data(void)\n+{\n+\tint k;\n+\n+\tfor (k = 0; k < my__child_summary_data.nr; k++) {\n+\t\tstruct child_summary_data *csd = my__child_summary_data.array[k];\n+\n+\t\tfree(csd->child_class);\n+\t\tfree(csd);\n+\t}\n+\n+\tfree(my__child_summary_data.array);\n+}\n+\n+static unsigned int is_interactive(const char *child_class)\n+{\n+\tif (child_class && *child_class) {\n+\t\tif (!strcmp(child_class, \"editor\"))\n+\t\t\treturn 1;\n+\t\tif (!strcmp(child_class, \"pager\"))\n+\t\t\treturn 1;\n+\t}\n+\treturn 0;\n+}\n+\n static struct child_data *alloc_child_data(const struct child_process *cmd)\n {\n \tstruct child_data *cd = xcalloc(1, sizeof(struct child_data));\n@@ -843,6 +946,9 @@ static struct child_data *alloc_child_data(const struct child_process *cmd)\n \tcd->is_running = 1;\n \tcd->is_git_cmd = cmd->git_cmd;\n \tcd->use_shell = cmd->use_shell;\n+\tcd->is_interactive = is_interactive(cmd->slog_child_class);\n+\tif (cmd->slog_child_class && *cmd->slog_child_class)\n+\t\tcd->child_class = xstrdup(cmd->slog_child_class);\n \n \tjw_init(&cd->jw_argv);\n \n@@ -895,6 +1001,11 @@ int slog_child_starting(const struct child_process *cmd)\n \t\t\tjw_object_intmax(&jw_data, \"child_id\", child_id);\n \t\t\tjw_object_bool(&jw_data, \"git_cmd\", cd->is_git_cmd);\n \t\t\tjw_object_bool(&jw_data, \"use_shell\", cd->use_shell);\n+\t\t\tjw_object_bool(&jw_data, \"is_interactive\",\n+\t\t\t\t cd->is_interactive);\n+\t\t\tif (cd->child_class)\n+\t\t\t\tjw_object_string(&jw_data, \"child_class\",\n+\t\t\t\t\t\t cd->child_class);\n \t\t\tjw_object_sub_jw(&jw_data, \"child_argv\", &cd->jw_argv);\n \t\t}\n \t\tjw_end(&jw_data);\n@@ -925,6 +1036,8 @@ void slog_child_ended(int child_id, int child_pid, int child_exit_code)\n \tcd->end_ns = getnanotime();\n \tcd->is_running = 0;\n \n+\tadd_child_to_summary_data(cd);\n+\n \t/* build data portion for a \"detail\" event */\n \tif (slog_want_detail_event(\"child\")) {\n \t\tstruct json_writer jw_data = JSON_WRITER_INIT;\n@@ -934,6 +1047,11 @@ void slog_child_ended(int child_id, int child_pid, int child_exit_code)\n \t\t\tjw_object_intmax(&jw_data, \"child_id\", child_id);\n \t\t\tjw_object_bool(&jw_data, \"git_cmd\", cd->is_git_cmd);\n \t\t\tjw_object_bool(&jw_data, \"use_shell\", cd->use_shell);\n+\t\t\tjw_object_bool(&jw_data, \"is_interactive\",\n+\t\t\t\t cd->is_interactive);\n+\t\t\tif (cd->child_class)\n+\t\t\t\tjw_object_string(&jw_data, \"child_class\",\n+\t\t\t\t\t\t cd->child_class);\n \t\t\tjw_object_sub_jw(&jw_data, \"child_argv\", &cd->jw_argv);\n \n \t\t\tjw_object_intmax(&jw_data, \"child_pid\", child_pid);\n@@ -957,6 +1075,7 @@ static void free_children(void)\n \t\tstruct child_data *cd = my__child_data.array[k];\n \n \t\tjw_release(&cd->jw_argv);\n+\t\tfree(cd->child_class);\n \t\tfree(cd);\n \t}\n \ndiff --git a/sub-process.c b/sub-process.c\nindex 8d2a170..93f7a52 100644\n--- a/sub-process.c\n+++ b/sub-process.c\n@@ -88,6 +88,7 @@ int subprocess_start(struct hashmap *hashmap, struct subprocess_entry *entry, co\n \tprocess->out = -1;\n \tprocess->clean_on_exit = 1;\n \tprocess->clean_on_exit_handler = subprocess_exit_handler;\n+\tprocess->slog_child_class = \"subprocess\";\n \n \terr = start_command(process);\n \tif (err) {\n-- \n2.9.3\n\n"},{"id":"352498","messageId":"20180713165621.52017-25-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 24/25] structured-logging: t0420 tests for interacitve child_summary","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:56:20Z","receivedAt":"2018-07-13T16:56:51Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nTest running a command with a fake pager and verify that a child_summary\nis generated.\n\nSigned-off-by: Jeff Hostetler \n---\n t/t0420-structured-logging.sh | 30 ++++++++++++++++++++++++++++++\n 1 file changed, 30 insertions(+)\n\ndiff --git a/t/t0420-structured-logging.sh b/t/t0420-structured-logging.sh\nindex 4ac404d..69f811a 100755\n--- a/t/t0420-structured-logging.sh\n+++ b/t/t0420-structured-logging.sh\n@@ -260,4 +260,34 @@ test_expect_success PERLJSON 'verify child start/end events during clone' '\n \tgrep \"row\\[1\\]\\.detail\\.data\\.child_exit_code 0\" paginated.out\" &&\n+\texport PAGER &&\n+\n+\ttest_commit initial\n+'\n+\n+test_expect_success TTY 'verify fake pager detected and process marked interactive' '\n+\ttest_when_finished \"rm \\\"$LOGFILE\\\" event_exit\" &&\n+\trm -f paginated.out &&\n+\trm -f \"$LOGFILE\" &&\n+\n+\ttest_terminal git log &&\n+\ttest -e paginated.out &&\n+\n+\tgrep -f key_cmd_exit \"$LOGFILE\" >event_exit &&\n+\n+\tperl \"$TEST_DIRECTORY\"/t0420/parse_json.perl parsed_exit &&\n+\n+\tgrep \"row\\[0\\]\\.child_summary\\.pager\\.count 1\" \n\nSigned-off-by: Jeff Hostetler \n---\n t/t0420-structured-logging.sh | 48 +++++++++++++++++++++++++++++++++++++++++++\n 1 file changed, 48 insertions(+)\n\ndiff --git a/t/t0420-structured-logging.sh b/t/t0420-structured-logging.sh\nindex a594af3..37c7e83 100755\n--- a/t/t0420-structured-logging.sh\n+++ b/t/t0420-structured-logging.sh\n@@ -140,4 +140,52 @@ test_expect_success PERLJSON 'parse JSON for checkout command' '\n \tgrep \"row\\[2\\]\\.sub_command path\" /dev/null &&\n+\n+\tgrep -f key_cmd_exit \"$LOGFILE\" >event_exit &&\n+\n+\tperl \"$TEST_DIRECTORY\"/t0420/parse_json.perl parsed_exit &&\n+\n+\tgrep \"row\\[0\\]\\.version\\.slog 0\" /dev/null &&\n+\n+\tgrep -f key_cmd_exit \"$LOGFILE\" >event_exit &&\n+\n+\tperl \"$TEST_DIRECTORY\"/t0420/parse_json.perl parsed_exit &&\n+\n+\tgrep \"row\\[0\\]\\.version\\.slog 0\" \n\nUse a SLOG timer to record the time spend in wt_status_collect_worktree(),\nwt_status_collect_changes_initial(), wt_status_collect_changes_index(),\nand wt_status_collect_untracked(). These are reported in the \"cmd_exit\"\nevent.\n\nSigned-off-by: Jeff Hostetler \n---\n wt-status.c | 20 ++++++++++++++++++++\n 1 file changed, 20 insertions(+)\n\ndiff --git a/wt-status.c b/wt-status.c\nindex d1c0514..f663a37 100644\n--- a/wt-status.c\n+++ b/wt-status.c\n@@ -580,8 +580,11 @@ static void wt_status_collect_updated_cb(struct diff_queue_struct *q,\n \n static void wt_status_collect_changes_worktree(struct wt_status *s)\n {\n+\tint slog_tid;\n \tstruct rev_info rev;\n \n+\tslog_tid = slog_start_timer(\"status\", \"worktree\");\n+\n \tinit_revisions(&rev, NULL);\n \tsetup_revisions(0, NULL, &rev, NULL);\n \trev.diffopt.output_format |= DIFF_FORMAT_CALLBACK;\n@@ -600,13 +603,18 @@ static void wt_status_collect_changes_worktree(struct wt_status *s)\n \trev.diffopt.rename_score = s->rename_score >= 0 ? s->rename_score : rev.diffopt.rename_score;\n \tcopy_pathspec(&rev.prune_data, &s->pathspec);\n \trun_diff_files(&rev, 0);\n+\n+\tslog_stop_timer(slog_tid);\n }\n \n static void wt_status_collect_changes_index(struct wt_status *s)\n {\n+\tint slog_tid;\n \tstruct rev_info rev;\n \tstruct setup_revision_opt opt;\n \n+\tslog_tid = slog_start_timer(\"status\", \"changes_index\");\n+\n \tinit_revisions(&rev, NULL);\n \tmemset(&opt, 0, sizeof(opt));\n \topt.def = s->is_initial ? empty_tree_oid_hex() : s->reference;\n@@ -636,12 +644,17 @@ static void wt_status_collect_changes_index(struct wt_status *s)\n \trev.diffopt.rename_score = s->rename_score >= 0 ? s->rename_score : rev.diffopt.rename_score;\n \tcopy_pathspec(&rev.prune_data, &s->pathspec);\n \trun_diff_index(&rev, 1);\n+\n+\tslog_stop_timer(slog_tid);\n }\n \n static void wt_status_collect_changes_initial(struct wt_status *s)\n {\n+\tint slog_tid;\n \tint i;\n \n+\tslog_tid = slog_start_timer(\"status\", \"changes_initial\");\n+\n \tfor (i = 0; i < active_nr; i++) {\n \t\tstruct string_list_item *it;\n \t\tstruct wt_status_change_data *d;\n@@ -672,10 +685,13 @@ static void wt_status_collect_changes_initial(struct wt_status *s)\n \t\t\toidcpy(&d->oid_index, &ce->oid);\n \t\t}\n \t}\n+\n+\tslog_stop_timer(slog_tid);\n }\n \n static void wt_status_collect_untracked(struct wt_status *s)\n {\n+\tint slog_tid;\n \tint i;\n \tstruct dir_struct dir;\n \tuint64_t t_begin = getnanotime();\n@@ -683,6 +699,8 @@ static void wt_status_collect_untracked(struct wt_status *s)\n \tif (!s->show_untracked_files)\n \t\treturn;\n \n+\tslog_tid = slog_start_timer(\"status\", \"untracked\");\n+\n \tmemset(&dir, 0, sizeof(dir));\n \tif (s->show_untracked_files != SHOW_ALL_UNTRACKED_FILES)\n \t\tdir.flags |=\n@@ -722,6 +740,8 @@ static void wt_status_collect_untracked(struct wt_status *s)\n \n \tif (advice_status_u_option)\n \t\ts->untracked_in_ms = (getnanotime() - t_begin) / 1000000;\n+\n+\tslog_stop_timer(slog_tid);\n }\n \n void wt_status_collect(struct wt_status *s)\n-- \n2.9.3\n\n"},{"id":"352501","messageId":"20180713165621.52017-12-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 11/25] structured-logging: add timer around do_read_index","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:56:07Z","receivedAt":"2018-07-13T16:56:58Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nUse a SLOG timer to record the time spent in do_read_index()\nand report it in the \"cmd_exit\" event.\n\nSigned-off-by: Jeff Hostetler \n---\n read-cache.c | 5 +++++\n 1 file changed, 5 insertions(+)\n\ndiff --git a/read-cache.c b/read-cache.c\nindex 3725882..df5dc87 100644\n--- a/read-cache.c\n+++ b/read-cache.c\n@@ -1900,6 +1900,7 @@ static void freshen_shared_index(const char *shared_index, int warn)\n int read_index_from(struct index_state *istate, const char *path,\n \t\t const char *gitdir)\n {\n+\tint slog_tid;\n \tuint64_t start = getnanotime();\n \tstruct split_index *split_index;\n \tint ret;\n@@ -1910,7 +1911,9 @@ int read_index_from(struct index_state *istate, const char *path,\n \tif (istate->initialized)\n \t\treturn istate->cache_nr;\n \n+\tslog_tid = slog_start_timer(\"index\", \"do_read_index\");\n \tret = do_read_index(istate, path, 0);\n+\tslog_stop_timer(slog_tid);\n \ttrace_performance_since(start, \"read cache %s\", path);\n \n \tsplit_index = istate->split_index;\n@@ -1926,7 +1929,9 @@ int read_index_from(struct index_state *istate, const char *path,\n \n \tbase_oid_hex = oid_to_hex(&split_index->base_oid);\n \tbase_path = xstrfmt(\"%s/sharedindex.%s\", gitdir, base_oid_hex);\n+\tslog_tid = slog_start_timer(\"index\", \"do_read_index\");\n \tret = do_read_index(split_index->base, base_path, 1);\n+\tslog_stop_timer(slog_tid);\n \tif (oidcmp(&split_index->base_oid, &split_index->base->oid))\n \t\tdie(\"broken index, expect %s in %s, got %s\",\n \t\t base_oid_hex, base_path,\n-- \n2.9.3\n\n"},{"id":"352502","messageId":"20180713165621.52017-10-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 09/25] structured-logging: add detail-event for lazy_init_name_hash","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:56:05Z","receivedAt":"2018-07-13T16:57:00Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nTeach git to generate a structured logging detail-event for\nlazy_init_name_hash(). This is marked as an \"index\" category\nevent and includes time and size data for the hashmaps.\n\nSigned-off-by: Jeff Hostetler \n---\n name-hash.c | 26 ++++++++++++++++++++++++++\n 1 file changed, 26 insertions(+)\n\ndiff --git a/name-hash.c b/name-hash.c\nindex 1638498..939b26a 100644\n--- a/name-hash.c\n+++ b/name-hash.c\n@@ -7,6 +7,8 @@\n */\n #define NO_THE_INDEX_COMPATIBILITY_MACROS\n #include \"cache.h\"\n+#include \"json-writer.h\"\n+#include \"structured-logging.h\"\n \n struct dir_entry {\n \tstruct hashmap_entry ent;\n@@ -603,6 +605,30 @@ static void lazy_init_name_hash(struct index_state *istate)\n \n \tistate->name_hash_initialized = 1;\n \ttrace_performance_since(start, \"initialize name hash\");\n+\n+\tif (slog_want_detail_event(\"index\")) {\n+\t\tstruct json_writer jw = JSON_WRITER_INIT;\n+\t\tuint64_t now_ns = getnanotime();\n+\t\tuint64_t elapsed_us = (now_ns - start) / 1000;\n+\n+\t\tjw_object_begin(&jw, slog_is_pretty());\n+\t\t{\n+\t\t\tjw_object_intmax(&jw, \"cache_nr\", istate->cache_nr);\n+\t\t\tjw_object_intmax(&jw, \"elapsed_us\", elapsed_us);\n+\t\t\tjw_object_intmax(&jw, \"dir_count\",\n+\t\t\t\t\t hashmap_get_size(&istate->dir_hash));\n+\t\t\tjw_object_intmax(&jw, \"dir_tablesize\",\n+\t\t\t\t\t istate->dir_hash.tablesize);\n+\t\t\tjw_object_intmax(&jw, \"name_count\",\n+\t\t\t\t\t hashmap_get_size(&istate->name_hash));\n+\t\t\tjw_object_intmax(&jw, \"name_tablesize\",\n+\t\t\t\t\t istate->name_hash.tablesize);\n+\t\t}\n+\t\tjw_end(&jw);\n+\n+\t\tslog_emit_detail_event(\"index\", \"lazy_init_name_hash\", &jw);\n+\t\tjw_release(&jw);\n+\t}\n }\n \n /*\n-- \n2.9.3\n\n"},{"id":"352503","messageId":"20180713165621.52017-6-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 05/25] structured-logging: set sub_command field for branch command","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:56:01Z","receivedAt":"2018-07-13T16:57:00Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nSet sub-command field for the various forms of the branch command.\n\nSigned-off-by: Jeff Hostetler \n---\n builtin/branch.c | 8 ++++++++\n 1 file changed, 8 insertions(+)\n\ndiff --git a/builtin/branch.c b/builtin/branch.c\nindex 5217ba3..fba516f 100644\n--- a/builtin/branch.c\n+++ b/builtin/branch.c\n@@ -689,10 +689,12 @@ int cmd_branch(int argc, const char **argv, const char *prefix)\n \t\tsetup_auto_pager(\"branch\", 1);\n \n \tif (delete) {\n+\t\tslog_set_sub_command_name(\"delete\");\n \t\tif (!argc)\n \t\t\tdie(_(\"branch name required\"));\n \t\treturn delete_branches(argc, argv, delete > 1, filter.kind, quiet);\n \t} else if (list) {\n+\t\tslog_set_sub_command_name(\"list\");\n \t\t/* git branch --local also shows HEAD when it is detached */\n \t\tif ((filter.kind & FILTER_REFS_BRANCHES) && filter.detached)\n \t\t\tfilter.kind |= FILTER_REFS_DETACHED_HEAD;\n@@ -716,6 +718,7 @@ int cmd_branch(int argc, const char **argv, const char *prefix)\n \t\tconst char *branch_name;\n \t\tstruct strbuf branch_ref = STRBUF_INIT;\n \n+\t\tslog_set_sub_command_name(\"edit\");\n \t\tif (!argc) {\n \t\t\tif (filter.detached)\n \t\t\t\tdie(_(\"Cannot give description to detached HEAD\"));\n@@ -741,6 +744,7 @@ int cmd_branch(int argc, const char **argv, const char *prefix)\n \t\tif (edit_branch_description(branch_name))\n \t\t\treturn 1;\n \t} else if (copy) {\n+\t\tslog_set_sub_command_name(\"copy\");\n \t\tif (!argc)\n \t\t\tdie(_(\"branch name required\"));\n \t\telse if (argc == 1)\n@@ -750,6 +754,7 @@ int cmd_branch(int argc, const char **argv, const char *prefix)\n \t\telse\n \t\t\tdie(_(\"too many branches for a copy operation\"));\n \t} else if (rename) {\n+\t\tslog_set_sub_command_name(\"rename\");\n \t\tif (!argc)\n \t\t\tdie(_(\"branch name required\"));\n \t\telse if (argc == 1)\n@@ -761,6 +766,7 @@ int cmd_branch(int argc, const char **argv, const char *prefix)\n \t} else if (new_upstream) {\n \t\tstruct branch *branch = branch_get(argv[0]);\n \n+\t\tslog_set_sub_command_name(\"new_upstream\");\n \t\tif (argc > 1)\n \t\t\tdie(_(\"too many arguments to set new upstream\"));\n \n@@ -784,6 +790,7 @@ int cmd_branch(int argc, const char **argv, const char *prefix)\n \t\tstruct branch *branch = branch_get(argv[0]);\n \t\tstruct strbuf buf = STRBUF_INIT;\n \n+\t\tslog_set_sub_command_name(\"unset_upstream\");\n \t\tif (argc > 1)\n \t\t\tdie(_(\"too many arguments to unset upstream\"));\n \n@@ -806,6 +813,7 @@ int cmd_branch(int argc, const char **argv, const char *prefix)\n \t} else if (argc > 0 && argc <= 2) {\n \t\tstruct branch *branch = branch_get(argv[0]);\n \n+\t\tslog_set_sub_command_name(\"create\");\n \t\tif (!branch)\n \t\t\tdie(_(\"no such branch '%s'\"), argv[0]);\n \n-- \n2.9.3\n\n"},{"id":"352504","messageId":"20180713165621.52017-4-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 03/25] structured-logging: add structured logging framework","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:55:59Z","receivedAt":"2018-07-13T16:57:02Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nTeach git to optionally generate structured logging data in JSON using\nthe json-writer API. \"cmd_start\" and \"cmd_end\" events are generated.\n\nStructured logging is only available when git is built with\nSTRUCTURED_LOGGING=1.\n\nStructured logging is only enabled when the config setting \"slog.path\"\nis set to an absolute pathname.\n\nSigned-off-by: Jeff Hostetler \n---\n Documentation/config.txt | 8 ++\n compat/mingw.h | 7 +\n config.c | 3 +\n git-compat-util.h | 9 ++\n git.c | 8 +-\n structured-logging.c | 366 +++++++++++++++++++++++++++++++++++++++++++++++\n structured-logging.h | 82 +++++++++++\n usage.c | 4 +\n 8 files changed, 486 insertions(+), 1 deletion(-)\n\ndiff --git a/Documentation/config.txt b/Documentation/config.txt\nindex ab641bf..c79f2bf 100644\n--- a/Documentation/config.txt\n+++ b/Documentation/config.txt\n@@ -3168,6 +3168,14 @@ showbranch.default::\n \tThe default set of branches for linkgit:git-show-branch[1].\n \tSee linkgit:git-show-branch[1].\n \n+slog.path::\n+\t(EXPERIMENTAL) Enable structured logging to a file. This must be\n+\tan absolute path. (Git must be compiled with STRUCTURED_LOGGING=1.)\n+\n+slog.pretty::\n+\t(EXPERIMENTAL) Pretty-print structured log data when true.\n+\t(Git must be compiled with STRUCTURED_LOGGING=1.)\n+\n splitIndex.maxPercentChange::\n \tWhen the split index feature is used, this specifies the\n \tpercent of entries the split index can contain compared to the\ndiff --git a/compat/mingw.h b/compat/mingw.h\nindex 571019d..d8d8cd3 100644\n--- a/compat/mingw.h\n+++ b/compat/mingw.h\n@@ -144,8 +144,15 @@ static inline int fcntl(int fd, int cmd, ...)\n \terrno = EINVAL;\n \treturn -1;\n }\n+\n /* bash cannot reliably detect negative return codes as failure */\n+#if defined(STRUCTURED_LOGGING)\n+#include \"structured-logging.h\"\n+#define exit(code) exit(strlog_exit_code((code) & 0xff))\n+#else\n #define exit(code) exit((code) & 0xff)\n+#endif\n+\n #define sigemptyset(x) (void)0\n static inline int sigaddset(sigset_t *set, int signum)\n { return 0; }\ndiff --git a/config.c b/config.c\nindex fbbf0f8..b27b024 100644\n--- a/config.c\n+++ b/config.c\n@@ -1476,6 +1476,9 @@ int git_default_config(const char *var, const char *value, void *dummy)\n \t\treturn 0;\n \t}\n \n+\tif (starts_with(var, \"slog.\"))\n+\t\treturn slog_default_config(var, value);\n+\n \t/* Add other config variables here and to Documentation/config.txt. */\n \treturn 0;\n }\ndiff --git a/git-compat-util.h b/git-compat-util.h\nindex 9a64998..f5352fd 100644\n--- a/git-compat-util.h\n+++ b/git-compat-util.h\n@@ -1239,4 +1239,13 @@ extern void unleak_memory(const void *ptr, size_t len);\n #define UNLEAK(var) do {} while (0)\n #endif\n \n+#include \"structured-logging.h\"\n+#if defined(STRUCTURED_LOGGING) && !defined(exit)\n+/*\n+ * Intercept all calls to exit() so that exit-code can be included\n+ * in the \"cmd_exit\" message written by the at-exit routine.\n+ */\n+#define exit(code) exit(slog_exit_code(code))\n+#endif\n+\n #endif\ndiff --git a/git.c b/git.c\nindex c2f48d5..024a40d 100644\n--- a/git.c\n+++ b/git.c\n@@ -413,6 +413,7 @@ static int run_builtin(struct cmd_struct *p, int argc, const char **argv)\n \t\tsetup_work_tree();\n \n \ttrace_argv_printf(argv, \"trace: built-in: git\");\n+\tslog_set_command_name(p->cmd);\n \n \tstatus = p->fn(argc, argv, prefix);\n \tif (status)\n@@ -700,7 +701,7 @@ static int run_argv(int *argcp, const char ***argv)\n \treturn done_alias;\n }\n \n-int cmd_main(int argc, const char **argv)\n+static int real_cmd_main(int argc, const char **argv)\n {\n \tconst char *cmd;\n \tint done_help = 0;\n@@ -779,3 +780,8 @@ int cmd_main(int argc, const char **argv)\n \n \treturn 1;\n }\n+\n+int cmd_main(int argc, const char **argv)\n+{\n+\treturn slog_wrap_main(real_cmd_main, argc, argv);\n+}\ndiff --git a/structured-logging.c b/structured-logging.c\nindex 702fd84..afa2224 100644\n--- a/structured-logging.c\n+++ b/structured-logging.c\n@@ -1,3 +1,10 @@\n+#include \"cache.h\"\n+#include \"config.h\"\n+#include \"version.h\"\n+#include \"json-writer.h\"\n+#include \"sigchain.h\"\n+#include \"argv-array.h\"\n+\n #if !defined(STRUCTURED_LOGGING)\n /*\n * Structured logging is not available.\n@@ -6,4 +13,363 @@\n \n #else\n \n+#define SLOG_VERSION 0\n+\n+static uint64_t my__start_time;\n+static uint64_t my__exit_time;\n+static int my__is_config_loaded;\n+static int my__is_enabled;\n+static int my__is_pretty;\n+static int my__signal;\n+static int my__exit_code;\n+static int my__pid;\n+static int my__wrote_start_event;\n+static int my__log_fd = -1;\n+\n+static char *my__log_path;\n+static char *my__command_name;\n+static char *my__sub_command_name;\n+\n+static struct argv_array my__argv = ARGV_ARRAY_INIT;\n+static struct json_writer my__errors = JSON_WRITER_INIT;\n+\n+/*\n+ * Write a single event to the structured log file.\n+ */\n+static void emit_event(struct json_writer *jw, const char *event_name)\n+{\n+\tif (my__log_fd == -1) {\n+\t\tmy__log_fd = open(my__log_path,\n+\t\t\t\t O_WRONLY | O_APPEND | O_CREAT,\n+\t\t\t\t 0644);\n+\t\tif (my__log_fd == -1) {\n+\t\t\twarning(\"slog: could not open '%s' for logging: %s\",\n+\t\t\t\tmy__log_path, strerror(errno));\n+\t\t\tmy__is_enabled = 0;\n+\t\t\treturn;\n+\t\t}\n+\t}\n+\n+\t/*\n+\t * A properly authored JSON string does not have a final NL\n+\t * (even when pretty-printing is enabled). Structured logging\n+\t * output should look like a series of terminated forms one\n+\t * per line. Temporarily append a NL to the buffer so that\n+\t * the disk write happens atomically.\n+\t */\n+\tstrbuf_addch(&jw->json, '\\n');\n+\tif (write(my__log_fd, jw->json.buf, jw->json.len) != jw->json.len)\n+\t\twarning(\"slog: could not write event '%s': %s\",\n+\t\t\tevent_name, strerror(errno));\n+\n+\tstrbuf_setlen(&jw->json, jw->json.len - 1);\n+}\n+\n+static void emit_start_event(void)\n+{\n+\tstruct json_writer jw = JSON_WRITER_INIT;\n+\n+\t/* build \"cmd_start\" event message */\n+\tjw_object_begin(&jw, my__is_pretty);\n+\t{\n+\t\tjw_object_string(&jw, \"event\", \"cmd_start\");\n+\t\tjw_object_intmax(&jw, \"clock_us\", (intmax_t)my__start_time);\n+\t\tjw_object_intmax(&jw, \"pid\", (intmax_t)my__pid);\n+\n+\t\tif (my__command_name && *my__command_name)\n+\t\t\tjw_object_string(&jw, \"command\", my__command_name);\n+\t\tif (my__sub_command_name && *my__sub_command_name)\n+\t\t\tjw_object_string(&jw, \"sub_command\", my__sub_command_name);\n+\n+\t\tjw_object_inline_begin_array(&jw, \"argv\");\n+\t\t{\n+\t\t\tint k;\n+\t\t\tfor (k = 0; k < my__argv.argc; k++)\n+\t\t\t\tjw_array_string(&jw, my__argv.argv[k]);\n+\t\t}\n+\t\tjw_end(&jw);\n+\t}\n+\tjw_end(&jw);\n+\n+\temit_event(&jw, \"cmd_start\");\n+\tjw_release(&jw);\n+\n+\tmy__wrote_start_event = 1;\n+}\n+\n+static void emit_exit_event(void)\n+{\n+\tstruct json_writer jw = JSON_WRITER_INIT;\n+\tuint64_t atexit_time = getnanotime() / 1000;\n+\n+\t/* close unterminated forms */\n+\tif (my__errors.json.len)\n+\t\tjw_end(&my__errors);\n+\n+\t/* build \"cmd_exit\" event message */\n+\tjw_object_begin(&jw, my__is_pretty);\n+\t{\n+\t\tjw_object_string(&jw, \"event\", \"cmd_exit\");\n+\t\tjw_object_intmax(&jw, \"clock_us\", (intmax_t)atexit_time);\n+\t\tjw_object_intmax(&jw, \"pid\", (intmax_t)my__pid);\n+\n+\t\tif (my__command_name && *my__command_name)\n+\t\t\tjw_object_string(&jw, \"command\", my__command_name);\n+\t\tif (my__sub_command_name && *my__sub_command_name)\n+\t\t\tjw_object_string(&jw, \"sub_command\", my__sub_command_name);\n+\n+\t\tjw_object_inline_begin_array(&jw, \"argv\");\n+\t\t{\n+\t\t\tint k;\n+\t\t\tfor (k = 0; k < my__argv.argc; k++)\n+\t\t\t\tjw_array_string(&jw, my__argv.argv[k]);\n+\t\t}\n+\t\tjw_end(&jw);\n+\n+\t\tjw_object_inline_begin_object(&jw, \"result\");\n+\t\t{\n+\t\t\tjw_object_intmax(&jw, \"exit_code\", my__exit_code);\n+\t\t\tif (my__errors.json.len)\n+\t\t\t\tjw_object_sub_jw(&jw, \"errors\", &my__errors);\n+\n+\t\t\tif (my__signal)\n+\t\t\t\tjw_object_intmax(&jw, \"signal\", my__signal);\n+\n+\t\t\tif (my__exit_time > 0)\n+\t\t\t\tjw_object_intmax(&jw, \"elapsed_core_us\",\n+\t\t\t\t\t\t my__exit_time - my__start_time);\n+\n+\t\t\tjw_object_intmax(&jw, \"elapsed_total_us\",\n+\t\t\t\t\t atexit_time - my__start_time);\n+\t\t}\n+\t\tjw_end(&jw);\n+\n+\t\tjw_object_inline_begin_object(&jw, \"version\");\n+\t\t{\n+\t\t\tjw_object_string(&jw, \"git\", git_version_string);\n+\t\t\tjw_object_intmax(&jw, \"slog\", SLOG_VERSION);\n+\t\t}\n+\t\tjw_end(&jw);\n+\t}\n+\tjw_end(&jw);\n+\n+\temit_event(&jw, \"cmd_exit\");\n+\tjw_release(&jw);\n+}\n+\n+static int cfg_path(const char *key, const char *value)\n+{\n+\tif (is_absolute_path(value)) {\n+\t\tmy__log_path = xstrdup(value);\n+\t\tmy__is_enabled = 1;\n+\t} else {\n+\t\twarning(\"'%s' must be an absolute path: '%s'\",\n+\t\t\tkey, value);\n+\t}\n+\n+\treturn 0;\n+}\n+\n+static int cfg_pretty(const char *key, const char *value)\n+{\n+\tmy__is_pretty = git_config_bool(key, value);\n+\treturn 0;\n+}\n+\n+int slog_default_config(const char *key, const char *value)\n+{\n+\tconst char *sub;\n+\n+\t/*\n+\t * git_default_config() calls slog_default_config() with \"slog.*\"\n+\t * k/v pairs. git_default_config() MAY or MAY NOT be called when\n+\t * cmd_() calls git_config().\n+\t *\n+\t * Remember if we've ever been called.\n+\t */\n+\tmy__is_config_loaded = 1;\n+\n+\tif (skip_prefix(key, \"slog.\", &sub)) {\n+\t\tif (!strcmp(sub, \"path\"))\n+\t\t\treturn cfg_path(key, value);\n+\t\tif (!strcmp(sub, \"pretty\"))\n+\t\t\treturn cfg_pretty(key, value);\n+\t}\n+\n+\treturn 0;\n+}\n+\n+static int lazy_load_config_cb(const char *key, const char * value, void *data)\n+{\n+\treturn slog_default_config(key, value);\n+}\n+\n+/*\n+ * If cmd_() did not cause slog_default_config() to be called\n+ * during git_config(), we try to lookup our config settings the first\n+ * time we actually need them.\n+ *\n+ * (We do this rather than using read_early_config() at initialization\n+ * because we want any \"-c key=value\" arguments to be included.)\n+ */\n+static inline void lazy_load_config(void)\n+{\n+\tif (my__is_config_loaded)\n+\t\treturn;\n+\tmy__is_config_loaded = 1;\n+\n+\tread_early_config(lazy_load_config_cb, NULL);\n+}\n+\n+int slog_is_enabled(void)\n+{\n+\tlazy_load_config();\n+\n+\treturn my__is_enabled;\n+}\n+\n+static void do_final_steps(int in_signal)\n+{\n+\tstatic int completed = 0;\n+\n+\tif (completed)\n+\t\treturn;\n+\tcompleted = 1;\n+\n+\tif (slog_is_enabled()) {\n+\t\tif (!my__wrote_start_event)\n+\t\t\temit_start_event();\n+\t\temit_exit_event();\n+\t\tmy__is_enabled = 0;\n+\t}\n+\n+\tif (my__log_fd != -1)\n+\t\tclose(my__log_fd);\n+\tfree(my__log_path);\n+\tfree(my__command_name);\n+\tfree(my__sub_command_name);\n+\targv_array_clear(&my__argv);\n+\tjw_release(&my__errors);\n+}\n+\n+static void slog_atexit(void)\n+{\n+\tdo_final_steps(0);\n+}\n+\n+static void slog_signal(int signo)\n+{\n+\tmy__signal = signo;\n+\n+\tdo_final_steps(1);\n+\n+\tsigchain_pop(signo);\n+\traise(signo);\n+}\n+\n+static void intern_argv(int argc, const char **argv)\n+{\n+\tint k;\n+\n+\tfor (k = 0; k < argc; k++)\n+\t\targv_array_push(&my__argv, argv[k]);\n+}\n+\n+/*\n+ * Collect basic startup information before cmd_main() has a chance\n+ * to alter the command line and before we have seen the config (to\n+ * know if logging is enabled). And since the config isn't loaded\n+ * until cmd_main() dispatches to cmd_(), we have to wait\n+ * and lazy-write the \"cmd_start\" event.\n+ *\n+ * This also implies that commands such as \"help\" and \"version\" that\n+ * don't need load the config won't generate any log data.\n+ */\n+static void initialize(int argc, const char **argv)\n+{\n+\tmy__start_time = getnanotime() / 1000;\n+\tmy__pid = getpid();\n+\n+\tintern_argv(argc, argv);\n+\n+\tatexit(slog_atexit);\n+\n+\t/*\n+\t * Put up backstop signal handler to ensure we get the \"cmd_exit\"\n+\t * event. This is primarily for when the pager throws SIGPIPE\n+\t * when the user quits.\n+\t */\n+\tsigchain_push(SIGPIPE, slog_signal);\n+}\n+\n+int slog_wrap_main(slog_fn_main_t fn_main, int argc, const char **argv)\n+{\n+\tint result;\n+\n+\tinitialize(argc, argv);\n+\tresult = fn_main(argc, argv);\n+\tslog_exit_code(result);\n+\n+\treturn result;\n+}\n+\n+void slog_set_command_name(const char *command_name)\n+{\n+\t/*\n+\t * Capture the command name even if logging is not enabled\n+\t * because we don't know if the config has been loaded yet by\n+\t * the cmd_() and/or it may be too early to force a\n+\t * lazy load.\n+\t */\n+\tif (my__command_name)\n+\t\tfree(my__command_name);\n+\tmy__command_name = xstrdup(command_name);\n+}\n+\n+void slog_set_sub_command_name(const char *sub_command_name)\n+{\n+\t/*\n+\t * Capture the sub-command name even if logging is not enabled\n+\t * because we don't know if the config has been loaded yet by\n+\t * the cmd_() and/or it may be too early to force a\n+\t * lazy load.\n+\t */\n+\tif (my__sub_command_name)\n+\t\tfree(my__sub_command_name);\n+\tmy__sub_command_name = xstrdup(sub_command_name);\n+}\n+\n+int slog_is_pretty(void)\n+{\n+\treturn my__is_pretty;\n+}\n+\n+int slog_exit_code(int exit_code)\n+{\n+\tmy__exit_time = getnanotime() / 1000;\n+\tmy__exit_code = exit_code;\n+\n+\treturn exit_code;\n+}\n+\n+void slog_error_message(const char *prefix, const char *fmt, va_list params)\n+{\n+\tstruct strbuf em = STRBUF_INIT;\n+\tva_list copy_params;\n+\n+\tif (prefix && *prefix)\n+\t\tstrbuf_addstr(&em, prefix);\n+\n+\tva_copy(copy_params, params);\n+\tstrbuf_vaddf(&em, fmt, copy_params);\n+\tva_end(copy_params);\n+\n+\tif (!my__errors.json.len)\n+\t\tjw_array_begin(&my__errors, my__is_pretty);\n+\tjw_array_string(&my__errors, em.buf);\n+\t/* leave my__errors array unterminated for now */\n+\n+\tstrbuf_release(&em);\n+}\n+\n #endif\ndiff --git a/structured-logging.h b/structured-logging.h\nindex c9e8c1d..61e98e6 100644\n--- a/structured-logging.h\n+++ b/structured-logging.h\n@@ -1,13 +1,95 @@\n #ifndef STRUCTURED_LOGGING_H\n #define STRUCTURED_LOGGING_H\n \n+typedef int (*slog_fn_main_t)(int, const char **);\n+\n #if !defined(STRUCTURED_LOGGING)\n /*\n * Structured logging is not available.\n * Stub out all API routines.\n */\n+#define slog_is_available() (0)\n+#define slog_default_config(k, v) (0)\n+#define slog_wrap_main(real_cmd_main, argc, argv) ((real_cmd_main)((argc), (argv)))\n+#define slog_set_command_name(n) do { } while (0)\n+#define slog_set_sub_command_name(n) do { } while (0)\n+#define slog_is_enabled() (0)\n+#define slog_is_pretty() (0)\n+#define slog_exit_code(exit_code) (exit_code)\n+#define slog_error_message(prefix, fmt, params) do { } while (0)\n \n #else\n \n+/*\n+ * Is structured logging available (compiled-in)?\n+ */\n+#define slog_is_available() (1)\n+\n+/*\n+ * Process \"slog.*\" config settings.\n+ */\n+int slog_default_config(const char *key, const char *value);\n+\n+/*\n+ * Wrapper for the \"real\" cmd_main(). Initialize structured logging if\n+ * enabled, run the given real_cmd_main(), and capture the return value.\n+ *\n+ * Note: common-main.c is shared by many top-level commands.\n+ * common-main.c:main() does common process setup before calling\n+ * the version of cmd_main() found in the executable. Some commands\n+ * SHOULD NOT do logging (such as t/helper/test-tool). Ones that do\n+ * need some common initialization/teardown.\n+ *\n+ * Use this function for any top-level command that should do logging.\n+ *\n+ * Usage:\n+ *\n+ * static int real_cmd_main(int argc, const char **argv)\n+ * {\n+ * ....the actual code for the command....\n+ * }\n+ *\n+ * int cmd_main(int argc, const char **argv)\n+ * {\n+ * return slog_wrap_main(real_cmd_main, argc, argv);\n+ * }\n+ * \n+ *\n+ * See git.c for an example.\n+ */ \n+int slog_wrap_main(slog_fn_main_t real_cmd_main, int argc, const char **argv);\n+\n+/*\n+ * Record a canonical command name and optional sub-command name for the\n+ * current process. For example, \"checkout\" and \"switch-branch\".\n+ */\n+void slog_set_command_name(const char *name);\n+void slog_set_sub_command_name(const char *name);\n+\n+/*\n+ * Is structured logging enabled?\n+ */\n+int slog_is_enabled(void);\n+\n+/*\n+ * Is JSON pretty-printing enabled?\n+ */\n+int slog_is_pretty(void);\n+\n+/*\n+ * Register the process exit code with the structured logging layer\n+ * and return it. This value will appear in the final \"cmd_exit\" event.\n+ *\n+ * Use this to wrap all calls to exit().\n+ * Use this before returning in main().\n+ */\n+int slog_exit_code(int exit_code);\n+\n+/*\n+ * Append formatted error message to the structured log result.\n+ * Messages from this will appear in the final \"cmd_exit\" event.\n+ */\n+void slog_error_message(const char *prefix, const char *fmt, va_list params);\n+\n #endif /* STRUCTURED_LOGGING */\n #endif /* STRUCTURED_LOGGING_H */\ndiff --git a/usage.c b/usage.c\nindex cc80333..5d48f6b 100644\n--- a/usage.c\n+++ b/usage.c\n@@ -27,12 +27,16 @@ static NORETURN void usage_builtin(const char *err, va_list params)\n \n static NORETURN void die_builtin(const char *err, va_list params)\n {\n+\tslog_error_message(\"fatal: \", err, params);\n+\n \tvreportf(\"fatal: \", err, params);\n \texit(128);\n }\n \n static void error_builtin(const char *err, va_list params)\n {\n+\tslog_error_message(\"error: \", err, params);\n+\n \tvreportf(\"error: \", err, params);\n }\n \n-- \n2.9.3\n\n"},{"id":"352505","messageId":"20180713165621.52017-3-git@jeffhostetler.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"[PATCH v1 02/25] structured-logging: add STRUCTURED_LOGGING=1 to Makefile","fromName":"","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-13T16:55:58Z","receivedAt":"2018-07-13T16:57:03Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler \n\nTeach the Makefile to take STRUCTURED_LOGGING=1 variable to\ncompile in/out structured logging feature.\n\nSigned-off-by: Jeff Hostetler \n---\n Makefile | 8 ++++++++\n structured-logging.c | 9 +++++++++\n structured-logging.h | 13 +++++++++++++\n 3 files changed, 30 insertions(+)\n create mode 100644 structured-logging.c\n create mode 100644 structured-logging.h\n\ndiff --git a/Makefile b/Makefile\nindex 39ca66b..ccc39bf 100644\n--- a/Makefile\n+++ b/Makefile\n@@ -442,6 +442,8 @@ all::\n # When cross-compiling, define HOST_CPU as the canonical name of the CPU on\n # which the built Git will run (for instance \"x86_64\").\n #\n+# Define STRUCTURED_LOGGING if you want structured logging to be available.\n+#\n # Define RUNTIME_PREFIX to configure Git to resolve its ancillary tooling and\n # support files relative to the location of the runtime binary, rather than\n # hard-coding them into the binary. Git installations built with RUNTIME_PREFIX\n@@ -955,6 +957,7 @@ LIB_OBJS += split-index.o\n LIB_OBJS += strbuf.o\n LIB_OBJS += streaming.o\n LIB_OBJS += string-list.o\n+LIB_OBJS += structured-logging.o\n LIB_OBJS += submodule.o\n LIB_OBJS += submodule-config.o\n LIB_OBJS += sub-process.o\n@@ -1326,6 +1329,10 @@ ifdef ZLIB_PATH\n endif\n EXTLIBS += -lz\n \n+ifdef STRUCTURED_LOGGING\n+\tBASIC_CFLAGS += -DSTRUCTURED_LOGGING\n+endif\n+\n ifndef NO_OPENSSL\n \tOPENSSL_LIBSSL = -lssl\n \tifdef OPENSSLDIR\n@@ -2543,6 +2550,7 @@ GIT-BUILD-OPTIONS: FORCE\n \t@echo TAR=\\''$(subst ','\\'',$(subst ','\\'',$(TAR)))'\\' >>$@+\n \t@echo NO_CURL=\\''$(subst ','\\'',$(subst ','\\'',$(NO_CURL)))'\\' >>$@+\n \t@echo NO_EXPAT=\\''$(subst ','\\'',$(subst ','\\'',$(NO_EXPAT)))'\\' >>$@+\n+\t@echo STRUCTURED_LOGGING=\\''$(subst ','\\'',$(subst ','\\'',$(STRUCTURED_LOGGING)))'\\' >>$@+\n \t@echo USE_LIBPCRE1=\\''$(subst ','\\'',$(subst ','\\'',$(USE_LIBPCRE1)))'\\' >>$@+\n \t@echo USE_LIBPCRE2=\\''$(subst ','\\'',$(subst ','\\'',$(USE_LIBPCRE2)))'\\' >>$@+\n \t@echo NO_LIBPCRE1_JIT=\\''$(subst ','\\'',$(subst ','\\'',$(NO_LIBPCRE1_JIT)))'\\' >>$@+\ndiff --git a/structured-logging.c b/structured-logging.c\nnew file mode 100644\nindex 0000000..702fd84\n--- /dev/null\n+++ b/structured-logging.c\n@@ -0,0 +1,9 @@\n+#if !defined(STRUCTURED_LOGGING)\n+/*\n+ * Structured logging is not available.\n+ * Stub out all API routines.\n+ */\n+\n+#else\n+\n+#endif\ndiff --git a/structured-logging.h b/structured-logging.h\nnew file mode 100644\nindex 0000000..c9e8c1d\n--- /dev/null\n+++ b/structured-logging.h\n@@ -0,0 +1,13 @@\n+#ifndef STRUCTURED_LOGGING_H\n+#define STRUCTURED_LOGGING_H\n+\n+#if !defined(STRUCTURED_LOGGING)\n+/*\n+ * Structured logging is not available.\n+ * Stub out all API routines.\n+ */\n+\n+#else\n+\n+#endif /* STRUCTURED_LOGGING */\n+#endif /* STRUCTURED_LOGGING_H */\n-- \n2.9.3\n\n"},{"id":"352520","messageId":"alpine.DEB.2.02.1807131150350.20559@nftneq.ynat.uz","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"Re: [PATCH v1 00/25] RFC: structured logging","fromName":"David Lang","fromEmail":"david@lang.hm","sentAt":"2018-07-13T18:51:34Z","receivedAt":"2018-07-13T18:51:55Z","isPatch":true,"sender":{"key":"david@lang.hm","avatar":null},"body":"Please make an option for git to write these logs to syslog, not just a local \nfile. Every modern syslog daemon has lots of tools to be able to deal with json \nmessages well.\n\nDavid Lang\n"},{"id":"352546","messageId":"20180714083401.GA2069@ruderich.org","threadId":"48879","inReplyTo":"20180713165621.52017-2-git@jeffhostetler.com","subject":"Re: [PATCH v1 01/25] structured-logging: design document","fromName":"Simon Ruderich","fromEmail":"simon@ruderich.org","sentAt":"2018-07-14T08:34:01Z","receivedAt":"2018-07-14T08:34:05Z","isPatch":true,"sender":{"key":"simon@ruderich.org","avatar":"https://avatars.githubusercontent.com/u/390994?v=4"},"body":"On Fri, Jul 13, 2018 at 04:55:57PM +0000, git@jeffhostetler.com wrote:\n> diff --git a/Documentation/technical/structured-logging.txt b/Documentation/technical/structured-logging.txt\n> new file mode 100644\n> index 0000000..794c614\n> --- /dev/null\n> +++ b/Documentation/technical/structured-logging.txt\n> @@ -0,0 +1,816 @@\n> [snip]\n>\n> +\"event\": \"cmd_start\"\n> +-------------------\n> +\n> +The \"cmd_start\" event is emitted when git starts when cmd_main() is\n> +called. In addition to the F1 fields, it contains the following\n> +fields (F2):\n> +\n> + \"argv\" : \n> +\n> + is an array of the original command line arguments given to the\n> + command (before git.c has a chance to remove the global options\n> + before the verb.\n\nMissing closing parentheses.\n\n> [snip]\n>\n> + are the values of the corresponding\n> + \"slog.{detail,timers,aux}\" config setting. Since these values\n> + control optional SLOG features and filtering, these are present\n> + to help post-processors know if an expected event did not happen\n> + or was simply filtered out. (Described later)\n\nPlease write out \"slog_detail, \"slog_timers\", etc. Using the\nabbreviated forms makes searching a pain.\n\nRegards\nSimon\n-- \n+ privacy is necessary\n+ using gnupg http://gnupg.org\n+ public key id: 0x92FEFDB7E44C32F9\n"},{"id":"352626","messageId":"a8f87adf-3f39-29b9-aef6-9c2e398f117a@jeffhostetler.com","threadId":"48879","inReplyTo":"alpine.DEB.2.02.1807131150350.20559@nftneq.ynat.uz","subject":"Re: [PATCH v1 00/25] RFC: structured logging","fromName":"Jeff Hostetler","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-16T13:29:50Z","receivedAt":"2018-07-16T13:29:56Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"\n\nOn 7/13/2018 2:51 PM, David Lang wrote:\n> Please make an option for git to write these logs to syslog, not just a \n> local file. Every modern syslog daemon has lots of tools to be able to \n> deal with json messages well.\n> \n> David Lang\n\nThat is certainly possible and we can easily add it in a later draft,\nbut for now I'd like to stay platform-neutral and just log events to a\nfile.\n\nMy main goal right now is to get consensus on the basic structured \nlogging framework -- the shape of the SLOG API, the event message\nformat, and etc.\n\nThanks,\nJeff\n"},{"id":"353622","messageId":"20180726090921.32232-1-szeder.dev@gmail.com","threadId":"48879","inReplyTo":"20180713165621.52017-4-git@jeffhostetler.com","subject":"Re: [PATCH v1 03/25] structured-logging: add structured logging framework","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-07-26T09:09:21Z","receivedAt":"2018-07-26T09:09:41Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"\n> +void slog_set_command_name(const char *command_name)\n> +{\n> +\t/*\n> +\t * Capture the command name even if logging is not enabled\n> +\t * because we don't know if the config has been loaded yet by\n> +\t * the cmd_() and/or it may be too early to force a\n> +\t * lazy load.\n> +\t */\n> +\tif (my__command_name)\n> +\t\tfree(my__command_name);\n> +\tmy__command_name = xstrdup(command_name);\n> +}\n> +\n> +void slog_set_sub_command_name(const char *sub_command_name)\n> +{\n> +\t/*\n> +\t * Capture the sub-command name even if logging is not enabled\n> +\t * because we don't know if the config has been loaded yet by\n> +\t * the cmd_() and/or it may be too early to force a\n> +\t * lazy load.\n> +\t */\n> +\tif (my__sub_command_name)\n> +\t\tfree(my__sub_command_name);\n\nPlease drop the condition in these two functions; free() handles NULL\narguments just fine.\n\n\n(Sidenote: what's the deal with these 'my__' prefixes anyway?)\n\n"},{"id":"353700","messageId":"7d027531-71f2-0a64-a5a2-4c477dd7133b@jeffhostetler.com","threadId":"48879","inReplyTo":"20180726090921.32232-1-szeder.dev@gmail.com","subject":"Re: [PATCH v1 03/25] structured-logging: add structured logging framework","fromName":"Jeff Hostetler","fromEmail":"git@jeffhostetler.com","sentAt":"2018-07-27T12:45:11Z","receivedAt":"2018-07-27T12:45:15Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"\n\nOn 7/26/2018 5:09 AM, SZEDER Gábor wrote:\n> \n>> +void slog_set_command_name(const char *command_name)\n>> +{\n>> +\t/*\n>> +\t * Capture the command name even if logging is not enabled\n>> +\t * because we don't know if the config has been loaded yet by\n>> +\t * the cmd_() and/or it may be too early to force a\n>> +\t * lazy load.\n>> +\t */\n>> +\tif (my__command_name)\n>> +\t\tfree(my__command_name);\n>> +\tmy__command_name = xstrdup(command_name);\n>> +}\n>> +\n>> +void slog_set_sub_command_name(const char *sub_command_name)\n>> +{\n>> +\t/*\n>> +\t * Capture the sub-command name even if logging is not enabled\n>> +\t * because we don't know if the config has been loaded yet by\n>> +\t * the cmd_() and/or it may be too early to force a\n>> +\t * lazy load.\n>> +\t */\n>> +\tif (my__sub_command_name)\n>> +\t\tfree(my__sub_command_name);\n> \n> Please drop the condition in these two functions; free() handles NULL\n> arguments just fine.\n\nsure.\n\n> \n> (Sidenote: what's the deal with these 'my__' prefixes anyway?)\n> \n\nsimply a way to identify file-scope variables and distinguish\nthem from local variables.\n\nJeff\n"},{"id":"354392","messageId":"13302a8c-a114-c3a7-65df-55f47f902126@gmail.com","threadId":"48879","inReplyTo":"20180713165621.52017-2-git@jeffhostetler.com","subject":"Re: [PATCH v1 01/25] structured-logging: design document","fromName":"Ben Peart","fromEmail":"peartben@gmail.com","sentAt":"2018-08-03T15:26:54Z","receivedAt":"2018-08-03T15:26:59Z","isPatch":true,"sender":{"key":"benpeart@microsoft.com","avatar":"https://avatars.githubusercontent.com/u/15252029?v=4"},"body":"\n\nOn 7/13/2018 12:55 PM, git@jeffhostetler.com wrote:\n> From: Jeff Hostetler \n> \n> Signed-off-by: Jeff Hostetler \n> ---\n> Documentation/technical/structured-logging.txt | 816 +++++++++++++++++++++++++\n> 1 file changed, 816 insertions(+)\n> create mode 100644 Documentation/technical/structured-logging.txt\n> \n> diff --git a/Documentation/technical/structured-logging.txt b/Documentation/technical/structured-logging.txt\n> new file mode 100644\n> index 0000000..794c614\n> --- /dev/null\n> +++ b/Documentation/technical/structured-logging.txt\n> @@ -0,0 +1,816 @@\n> +Structured Logging\n> +==================\n> +\n> +Structured Logging (SLOG) is an optional feature to allow Git to\n> +generate structured log data for executed commands. This includes\n> +command line arguments, command run times, error codes and messages,\n> +child process information, time spent in various critical functions,\n> +and repository data-shape information. Data is written to a target\n> +log file in JSON[1,2,3] format.\n> +\n> +SLOG is disabled by default. Several steps are required to enable it:\n> +\n> +1. Add the compile-time flag \"STRUCTURED_LOGGING=1\" when building git\n> + to include the SLOG routines in the git executable.\n> +\n\nIs the intent to remove this compile-time flag before this is merged? \nWith it off by default in builds, the audience for this is limited to \nthose who build their own/custom versions of git. I can see other \norganizations wanting to use this that don't have a custom fork of git \nthey build and install on their users machines.\n\nLike the GIT_TRACE mechanism today, I think this should be compiled in \nbut turned off via the default settings by default.\n\n> +2. Set \"slog.*\" config settings[5] to enable SLOG in your repo.\n> +\n> +\n> +Motivation\n> +==========\n> +\n> +Git users may be faced with scenarios that are surprisingly slow or\n> +produce unexpected results. And Git developers may have difficulty\n> +reproducing these experiences. Structured logging allows users to\n> +provide developers with additional usage, performance and error data\n> +that can help diagnose and debug issues.\n> +\n> +Many Git hosting providers and users with many developers have bespoke\n> +efforts to help troubleshoot problems; for example, command wrappers,\n> +custom pre- and post-command hooks, and custom instrumentation of Git\n> +code. These are inefficient and/or difficult to maintain. The goal\n> +of SLOG is to provide this data as efficiently as possible.\n> +\n> +And having structured rather than free format log data, will help\n> +developers with their analysis.\n> +\n> +\n> +Background (Git Merge 2018 Barcelona)\n> +=====================================\n> +\n> +Performance and/or error logging was discussed during the contributor's\n> +summit in Barcelona. Here are the relevant notes from the meeting\n> +minutes[6].\n> +\n> +> Performance misc (Ævar)\n> +> -----------------------\n> +> [...]\n> +> - central error reporting for git\n> +> - `git status` logging\n> +> - git config that collects data, pushes to known endpoint with `git push`\n> +> - pre_command and post_command hooks, for logs\n> +> - `gvfs diagnose` that looks at packfiles, etc\n> +> - detect BSODs, etc\n> +> - Dropbox writes out json with index properties and command-line\n> +> information for status/fetch/push, fork/execs external tool to upload\n> +> - windows trace facility; would be nice to have cross-platform\n> +> - would hosting providers care?\n> +> - zipfile of logs to give when debugging\n> +> - sanitizing data is harder\n> +> - more in a company setting\n> +> - fileshare to upload zipfile\n> +> - most of the errors are proxy when they shouldn't, wrong proxy, proxy\n> +> specific to particular URL; so upload endpoint wouldn't work\n> +> - GIT_TRACE is supposed to be that (for proxy)\n> +> - but we need more trace variables\n> +> - series to make tracing cheaper\n> +> - except that curl selects the proxy\n> +> - trace should have an API, so it can call an executable\n> +> - dump to .git/traces/... and everything else happens externally\n> +> - tools like visual studio can't set GIT_TRACE, so\n> +> - sourcetree has seen user environments where commands just take forever\n> +> - third-party tools like perf/strace - could we be better leveraging those?\n> +> - distribute turn-key solution to handout to collect more data?\n> +\n\nWhile it makes sense to have clear goals in the design document, the \nmotivation and background sections feel somehow out of place. I'd \nrecommend you clearly articulate the design goals and drop the \nbackground data that led you to the goals.\n\n> +\n> +A Quick Example\n> +===============\n> +\n> +Note: JSON pretty-printing is enabled in all of the examples shown in\n> +this document. When pretty-printing is turned off, each event is\n> +written on a single line. Pretty-printing is intended for debugging.\n> +It should be turned off in production to make post-processing easier.\n> + > + $ git config slog.pretty \n> +\n\nnit - I'd move this \"Note:\" section to the end of your \"A Quick \nExample.\" While it's good to understand about pretty printing, its not \nthe first or most important thing.\n\n> +Here is a quick example showing SLOG data for \"git status\". This\n> +example has all optional features turned off. It contains 2 events.\n> +The first is generated when the command started and the second when it\n> +ended.\n> +\n> +{\n> + \"event\": \"cmd_start\",\n> + \"clock_us\": 1530273550667800,\n> + \"pid\": 107270,\n> + \"sid\": \"1530273550667800-107270\",\n> + \"command\": \"status\",\n> + \"argv\": [\n> + \"./git\",\n> + \"status\"\n> + ]\n> +}\n> +{\n> + \"event\": \"cmd_exit\",\n> + \"clock_us\": 1530273550680460,\n> + \"pid\": 107270,\n> + \"sid\": \"1530273550667800-107270\",\n> + \"command\": \"status\",\n> + \"argv\": [\n> + \"./git\",\n> + \"status\"\n> + ],\n> + \"result\": {\n> + \"exit_code\": 0,\n> + \"elapsed_core_us\": 12573,\n> + \"elapsed_total_us\": 12660\n> + },\n> + \"version\": {\n> + \"git\": \"2.18.0.rc0.83.gde7fb7c\",\n> + \"slog\": 0\n> + },\n> + \"config\": {\n> + \"slog\": {\n> + \"detail\": 0,\n> + \"timers\": 0,\n> + \"aux\": 0\n> + }\n> + }\n> +}\n> +\n> +Both events fields describing the event name, the event time (in\n\nMaybe \"Both events have fields describing the event name...\"\n\n> +microseconds since the epoch), the OS process-id, a unique session-id\n> +(described later), the normalized command name, and a vector of the\n> +original command line arguments.\n> +\n> +The \"cmd_exit\" event additionally contains information about how the\n> +process exited, the elapsed time, the version of git and the SLOG\n> +format, and important SLOG configuration settings.\n> +\n\nAt first glance, the SLOG configuration settings seem out of place but \nI'll read on to see why they are needed with every cmd_exit event...\n\n> +The fields in the \"cmd_start\" event are replicated in the \"cmd_exit\"\n> +event. This allows log file post-processors to operate in 2 modes:\n> +\n> +1. Just look at the \"cmd_exit\" events. This us useful if you just\n> + want to analyze the command summary data.\n> +\n> +2. Look at the \"cmd_start\" and \"cmd_exit\" events as bracketing a time\n> + span and examine the detailed activity between. For example, SLOG\n> + can optionally generate \"detail\" events when spawning child\n> + processes and those processes may themselves generate \"cmd_start\"\n> + and \"cmd_exit\" events. The (top-level) \"cmd_start\" event serves as\n> + the starting bracket of all of that activity.\n> +\n\nI'm assuming the sid is what will enable correlating the child process \nevents with the outer command?\n\n> +\n> +Target Log File\n> +===============\n> +\n> +SLOG writes events to a log file. File logging works much like\n> +GIT_TRACE where events are appended to a file on disk.\n> +\n> +Logging is enabled if the config variable \"slog.path\" is set to an\n> +absolute pathname.\n> +\n> +As with GIT_TRACE, this file is local and private to the user's\n> +system. Log file management and rotation is beyond the scope of the\n> +SLOG effort.\n> +\n> +Similarly, if a user wants to provide this data to a developer, they\n> +must explicitly make these log files available; SLOG does not\n> +broadcast any of this information. It is up to the users of this\n> +system to decide if any sensitive information should be sanitized, and\n> +how to export the logs.\n> +\n\nIt's good to clarify this.\n\n> +\n> +Comparison with GIT_TRACE\n> +=========================\n> +\n> +SLOG is very similar to the existing GIT_TRACE[4] API because both\n> +write event messages at various points during a command. However,\n> +there are some fundamental differences that warrant it being\n> +considered a separate feature rather than just another\n> +GIT_TRACE_:\n> +\n\nBut it does make me wonder if we need to keep both systems. If there \nare two, as a developer I need to know which I should use. What is the \ncriteria I should use to decide between adding GIT_TRACE and SLOG \ntracing? It seems like it would be best if we could converge on a \nsingle tracing model.\n\n> +1. GIT_TRACE events are unrelated, line-by-line logging. SLOG has\n> + line-by-line events that show command progress and can serve as\n> + structured debug messages. SLOG also supports accumulating summary\n> + data (such as timers) that are automatically added to the final\n> + `cmd_exit` event.\n> +\n> +2. GIT_TRACE events are unstructured free format printf-style messages\n> + which makes post-processing difficult. SLOG events are written in\n> + JSON and can be easily parsed using Perl, Python, and other tools.\n> +\n> +3. SLOG uses a well-defined API to build SLOG events containing\n> + well-defined fields to make post-command analysis easier.\n> +\n> +4. It should be easier to filter/redact sensitive information from\n> + SLOG data than from free form data.\n> +\n> +5. GIT_TRACE events are controlled by one or more global environment\n> + variables which makes it awkward to selectively log some repos and\n> + not others. SLOG events are controlled by a few configuration\n> + settings[5]. Users (or system administrators) can configure\n> + logging using repo-local or global config settings.\n> +\n> +6. GIT_TRACE events do not identify the git process. This makes it\n> + difficult to associate all of events from a particular command.\n> + Each SLOG event contains a session id to allow all events for a\n> + command to be identified.\n> +\n> +7. Some git commands spawn child git commands. GIT_TRACE has no\n> + mechanism to associate events from a child process with the parent\n> + process. SLOG session ids allow child/parent relationships to be\n> + tracked (even if there is an intermediate /bin/sh process between\n> + them).\n> +\n> +8. GIT_TRACE supports logging to a file or stderr. SLOG only logs to\n> + a file.\n> +\n> +9. Smashing SLOG into GIT_TRACE doesn't feel like a good fit. The 2\n> + APIs share nothing other than the concept that they write logging\n> + data.\n> +\n\nIs SLOG a superset of GIT_TRACE? If not, could it be? While SLOG can't \nbe smashed into GIT_TRACE, can the functionality of GIT_TRACE be \nsubsumed by SLOG so that we can converge on a single tracing system?\n\nI'd like to see a design goal for this effort to be that we come up with \na single tracing mechanism that meets _all_ the requirements (including \nthose currently met by GIT_TRACE).\n\n> +\n> +[1] http://json.org/\n> +[2] http://www.ietf.org/rfc/rfc7159.txt\n> +[3] See UTF-8 limitations described in json-writer.h\n> +[4] Documentation/technical/api-trace.txt\n> +[5] See \"slog.*\" in Documentation/config.txt\n> +[6] https://public-inbox.org/git/20180313004940.GG61720@google.com/t/\n> +\n> +\n> +SLOG Format (V0)\n> +================\n> +\n> +SLOG writes a series of events to the log target. Each event is a\n> +self-describing JSON object.\n> +\n> + LF\n> + LF\n> + LF\n> + ...\n> +\n> +Each event record in the log file is an independent and complete JSON\n> +object. JSON parsers should process the file line-by-line rather than\n> +trying to parse the entire file into a single object.\n> +\n> + Note: It may be difficult for parsers to find record boundaries if\n> + pretty-printing is enabled, so it recommended that pretty-printing\n> + only be enabled for interactive debugging and analysis.\n> +\n> +Every contains the following fields (F1):\n> +\n> + \"event\" : \n> + \"clock_us\" : \n> + \"pid\" : \n> + \"sid\" : \n> +\n> + \"command\" : \n> + \"sub_command\" : (optional)\n> +\n> + is one of \"cmd_start\", \"cmd_end\", or \"detail\".\n> +\n> + is the time of the event in microseconds since the epoch.\n> +\n> + is the process-id (from getpid()).\n> +\n> + is a session-id. (Described later)\n> +\n> + is a (possibly normalized) command name. This is\n> + usually taken from the cmd_struct[] table after git parses the\n> + command line and calls the appropriate cmd_() function.\n> + Having it in a top-level field saves post-processors from having\n> + to re-parse the command line to discover it.\n> +\n> + further qualifies the command. This field is\n> + present for common commands that have multiple command modes. For\n> + example, checkout can either change branches and do a full\n> + checkout or it can checkout (refresh) an individual file. A\n> + post-processor wanting to compute percentiles for the time spent\n> + by branch-changing checkouts could easily filter out the\n> + individual file checkouts (and without having to re-parse the\n> + command line).\n> +\n> + The set of sub_command values are command-specific and are not\n> + listed here.\n\nThe sub-command definition seems a little squishy but I guess since you\nhave the entire set of command line arguments, it's really just a hint\nas you could always drop back to looking at the arguments yourself.\n\n> +\n> +\"event\": \"cmd_start\"\n> +-------------------\n> +\n> +The \"cmd_start\" event is emitted when git starts when cmd_main() is\n> +called. In addition to the F1 fields, it contains the following\n> +fields (F2):\n> +\n> + \"argv\" : \n> +\n> + is an array of the original command line arguments given to the\n> + command (before git.c has a chance to remove the global options\n> + before the verb.\n> +\n> +\n> +\"event\": \"cmd_exit\"\n> +-------------------\n> +\n> +The \"cmd_exit\" event is emitted immediately before git exits (during\n> +an atexit() routine). It contains the F1 and F2 fields as described\n> +above. It also contains the the following fields (F3):\n> +\n> + \"result.exit_code\" : \n> + \"result.errors\" : (optional)\n> + \"result.elapsed_core_us\" : \n> + \"result.elapsed_total_us\" : \n> + \"result.signal\" : (optional)\n> +\n> + \"verion.git\" : \n> + \"version.slog\" : \n> +\n> + \"config.slog.detail\" : \n> + \"config.slog.timers\" : \n> + \"config.slog.aux\" : \n> + \"config.*.*\" : (optional)\n> +\n> + \"timers\" : (optional)\n> + \"aux\" : (optional)\n> +\n> + \"child_summary\" : (optional)\n> +\n> + is the value passed to exit() or returned from main().\n> +\n> + is an array of messages passed to the die()\n> + and error() functions.\n> +\n> + is the elapsed time from start until exit()\n> + was called or main() returned.\n> +\n> + is the elapsed time from start until the slog\n> + atexit routine was called. This time will include any time\n> + required to shut down or wait for the pager to complete.\n> +\n\nI wonder how valuable the difference is between these two and if we \ncould simply drop the \n\n> + is present if the command was stopped by a single,\n\ns/single/signal\n\n> + such as a SIGPIPE when the pager is quit.\n> +\n> + is the git version number as reported by \"git version\".\n> +\n> + is the SLOG format version.\n> +\n> + are the values of the corresponding\n> + \"slog.{detail,timers,aux}\" config setting. Since these values\n> + control optional SLOG features and filtering, these are present\n> + to help post-processors know if an expected event did not happen\n> + or was simply filtered out. (Described later)\n> +\n> + is a place for developers to add additional\n> + important config settings to the log. This is not intended as a\n> + dumping ground for all config settings, but rather only ones that\n> + might affect performance or allow A/B testing in production.\n> +\n> + is a structure of any SLOG timers used during the process.\n> + (Described later)\n> +\n> + is a structure of any \"aux data\" generated during the process.\n> + (Described later)\n> +\n> + is a structure summarizing child processes by class.\n> + (Described later)\n> +\n> +\n> +\"event\": \"detail\" and config setting \"slog.detail\"\n> +--------------------------------------------------\n> +\n> +The \"detail\" event is used to report progress and/or debug information\n> +during a command. It is a line-by-line (rather than summary) event.\n> +Like GIT_TRACE_, detail events are classified by \"category\" and\n> +may be included or omitted based on the \"slog.detail\" config setting.\n> +\n> +Here are 3 example \"detail\" events:\n> +\n> +{\n> + \"event\": \"detail\",\n> + \"clock_us\": 1530273485479387,\n> + \"pid\": 107253,\n> + \"sid\": \"1530273485473820-107253\",\n> + \"command\": \"status\",\n> + \"detail\": {\n> + \"category\": \"index\",\n> + \"label\": \"lazy_init_name_hash\",\n> + \"data\": {\n> + \"cache_nr\": 3269,\n> + \"elapsed_us\": 195,\n> + \"dir_count\": 0,\n> + \"dir_tablesize\": 4096,\n> + \"name_count\": 3269,\n> + \"name_tablesize\": 4096\n> + }\n> + }\n> +}\n> +{\n> + \"event\": \"detail\",\n> + \"clock_us\": 1530283184051338,\n> + \"pid\": 109679,\n> + \"sid\": \"1530283180782876-109679\",\n> + \"command\": \"fetch\",\n> + \"detail\": {\n> + \"category\": \"child\",\n> + \"label\": \"child_starting\",\n> + \"data\": {\n> + \"child_id\": 3,\n> + \"git_cmd\": true,\n> + \"use_shell\": false,\n> + \"is_interactive\": false,\n> + \"child_argv\": [\n> + \"gc\",\n> + \"--auto\"\n> + ]\n> + }\n> + }\n> +}\n> +{\n> + \"event\": \"detail\",\n> + \"clock_us\": 1530283184053158,\n> + \"pid\": 109679,\n> + \"sid\": \"1530283180782876-109679\",\n> + \"command\": \"fetch\",\n> + \"detail\": {\n> + \"category\": \"child\",\n> + \"label\": \"child_ended\",\n> + \"data\": {\n> + \"child_id\": 3,\n> + \"git_cmd\": true,\n> + \"use_shell\": false,\n> + \"is_interactive\": false,\n> + \"child_argv\": [\n> + \"gc\",\n> + \"--auto\"\n> + ],\n> + \"child_pid\": 109684,\n> + \"child_exit_code\": 0,\n> + \"child_elapsed_us\": 1819\n> + }\n> + }\n> +}\n> +\n> +A detail event contains the common F1 described earlier. It also\n> +contains 2 fixed fields and 1 variable field:\n> +\n> + \"detail.category\" : \n> + \"detail.label\" : \n> + \"detail.data\" : \n> +\n> + is the \"category\" name for the event. This is\n> + similar to GIT_TRACE_. In the example above we have 1\n> + \"index\" and 2 \"child\" category events.\n> +\n> + If the config setting \"slog.detail\" is true or contains this\n> + category name, the event will be generated. If \"slog.detail\"\n> + is false, no detail events will be generated.\n> +\n> + $ git config slog.detail true\n> + $ git config slog.detail child,index,status\n> + $ git config slog.detail false\n> +\n> + is a descriptive label for the event. It may be the\n> + name of a function or any meaningful value.\n> +\n> + is a JSON structure containing context-specific data for\n> + the event. This replaces the need for printf-like trace messages.\n\nHmm, couldn't this (a new \"Trace Detail Event) be used to help replace \nthe existing GIT_TRACE mechanism? I think one missing piece is a \nformatting option other than \"pretty.\" Perhaps another field that is a \nformat string that can be used to give it a richer human readable output?\n\nOverall this looks very robust and capable. Clearly my biggest feedback \nis that I'd like to see this be able to replace the existing GIT_TRACE \nand GIT_TRACE_PERFORMANCE support. Having two different mechanisms \nseems unnecessarily complex and will increase the mental burden when \nadding tracing. It also doubles the code we need to \nwrite/debug/document/support. I'd hate to see callers of the tracing \ncode having to double up and including calls to both tracing mechanisms.\n\nI'm OK if this is a goal and migrating the existing calls to GIT_TRACE \nare cleaned up over time. It may be a nice intermediate step if the \nexisting macros could be re-implemented to sit on top of the new SLOG \ninfrastructure. This would certainly make it easier to migrate the code \nbase over time.\n\n\n"},{"id":"354994","messageId":"f582d8c2-bdcb-ee5c-18bc-9e351a4442f9@jeffhostetler.com","threadId":"48879","inReplyTo":"13302a8c-a114-c3a7-65df-55f47f902126@gmail.com","subject":"Re: [PATCH v1 01/25] structured-logging: design document","fromName":"Jeff Hostetler","fromEmail":"git@jeffhostetler.com","sentAt":"2018-08-09T14:30:26Z","receivedAt":"2018-08-09T14:30:32Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"\n\nOn 8/3/2018 11:26 AM, Ben Peart wrote:\n> \n> \n> On 7/13/2018 12:55 PM, git@jeffhostetler.com wrote:\n>> From: Jeff Hostetler \n>>\n>> Signed-off-by: Jeff Hostetler \n>> ---\n>>   Documentation/technical/structured-logging.txt | 816 \n>> +++++++++++++++++++++++++\n>>   1 file changed, 816 insertions(+)\n>>   create mode 100644 Documentation/technical/structured-logging.txt\n>>\n>> diff --git a/Documentation/technical/structured-logging.txt \n>> b/Documentation/technical/structured-logging.txt\n>> new file mode 100644\n>> index 0000000..794c614\n>> --- /dev/null\n>> +++ b/Documentation/technical/structured-logging.txt\n>> @@ -0,0 +1,816 @@\n>> +Structured Logging\n>> +==================\n>> +\n>> +Structured Logging (SLOG) is an optional feature to allow Git to\n>> +generate structured log data for executed commands.  This includes\n>> +command line arguments, command run times, error codes and messages,\n>> +child process information, time spent in various critical functions,\n>> +and repository data-shape information.  Data is written to a target\n>> +log file in JSON[1,2,3] format.\n>> +\n>> +SLOG is disabled by default.  Several steps are required to enable it:\n>> +\n>> +1. Add the compile-time flag \"STRUCTURED_LOGGING=1\" when building git\n>> +   to include the SLOG routines in the git executable.\n>> +\n> \n> Is the intent to remove this compile-time flag before this is merged? \n> With it off by default in builds, the audience for this is limited to \n> those who build their own/custom versions of git. I can see other \n> organizations wanting to use this that don't have a custom fork of git \n> they build and install on their users machines.\n> \n> Like the GIT_TRACE mechanism today, I think this should be compiled in \n> but turned off via the default settings by default.\n\nI would like to get rid of this compile-time flag and just have it\nbe available to those who want to use it. And defaulted to off.\nBut I wasn't sure what kind of reaction or level of interest this\nfeature would receive from the mailing list.\n\n\n>> +2. Set \"slog.*\" config settings[5] to enable SLOG in your repo.\n>> +\n>> +\n>> +Motivation\n>> +==========\n>> +\n>> +Git users may be faced with scenarios that are surprisingly slow or\n>> +produce unexpected results.  And Git developers may have difficulty\n>> +reproducing these experiences.  Structured logging allows users to\n>> +provide developers with additional usage, performance and error data\n>> +that can help diagnose and debug issues.\n>> +\n>> +Many Git hosting providers and users with many developers have bespoke\n>> +efforts to help troubleshoot problems; for example, command wrappers,\n>> +custom pre- and post-command hooks, and custom instrumentation of Git\n>> +code.  These are inefficient and/or difficult to maintain.  The goal\n>> +of SLOG is to provide this data as efficiently as possible.\n>> +\n>> +And having structured rather than free format log data, will help\n>> +developers with their analysis.\n>> +\n>> +\n>> +Background (Git Merge 2018 Barcelona)\n>> +=====================================\n>> +\n>> +Performance and/or error logging was discussed during the contributor's\n>> +summit in Barcelona.  Here are the relevant notes from the meeting\n>> +minutes[6].\n>> +\n>> +> Performance misc (Ævar)\n>> +> -----------------------\n>> +> [...]\n>> +>  - central error reporting for git\n>> +>    - `git status` logging\n>> +>    - git config that collects data, pushes to known endpoint with \n>> `git push`\n>> +>    - pre_command and post_command hooks, for logs\n>> +>    - `gvfs diagnose` that looks at packfiles, etc\n>> +>    - detect BSODs, etc\n>> +>    - Dropbox writes out json with index properties and command-line\n>> +>        information for status/fetch/push, fork/execs external tool \n>> to upload\n>> +>    - windows trace facility; would be nice to have cross-platform\n>> +>    - would hosting providers care?\n>> +>    - zipfile of logs to give when debugging\n>> +>    - sanitizing data is harder\n>> +>    - more in a company setting\n>> +>    - fileshare to upload zipfile\n>> +>    - most of the errors are proxy when they shouldn't, wrong proxy, \n>> proxy\n>> +>        specific to particular URL; so upload endpoint wouldn't work\n>> +>    - GIT_TRACE is supposed to be that (for proxy)\n>> +>    - but we need more trace variables\n>> +>    - series to make tracing cheaper\n>> +>    - except that curl selects the proxy\n>> +>    - trace should have an API, so it can call an executable\n>> +>    - dump to .git/traces/... and everything else happens externally\n>> +>    - tools like visual studio can't set GIT_TRACE, so\n>> +>    - sourcetree has seen user environments where commands just take \n>> forever\n>> +>    - third-party tools like perf/strace - could we be better \n>> leveraging those?\n>> +>    - distribute turn-key solution to handout to collect more data?\n>> +\n> \n> While it makes sense to have clear goals in the design document, the \n> motivation and background sections feel somehow out of place.  I'd \n> recommend you clearly articulate the design goals and drop the \n> background data that led you to the goals.\n\ngood point. thanks.\n\n\n>> +\n>> +A Quick Example\n>> +===============\n>> +\n>> +Note: JSON pretty-printing is enabled in all of the examples shown in\n>> +this document.  When pretty-printing is turned off, each event is\n>> +written on a single line.  Pretty-printing is intended for debugging.\n>> +It should be turned off in production to make post-processing easier.\n>> + > +    $ git config slog.pretty \n>> +\n> \n> nit - I'd move this \"Note:\" section to the end of your \"A Quick \n> Example.\" While it's good to understand about pretty printing, its not \n> the first or most important thing.\n> \n>> +Here is a quick example showing SLOG data for \"git status\".  This\n>> +example has all optional features turned off.  It contains 2 events.\n>> +The first is generated when the command started and the second when it\n>> +ended.\n>> +\n>> +{\n>> +  \"event\": \"cmd_start\",\n>> +  \"clock_us\": 1530273550667800,\n>> +  \"pid\": 107270,\n>> +  \"sid\": \"1530273550667800-107270\",\n>> +  \"command\": \"status\",\n>> +  \"argv\": [\n>> +    \"./git\",\n>> +    \"status\"\n>> +  ]\n>> +}\n>> +{\n>> +  \"event\": \"cmd_exit\",\n>> +  \"clock_us\": 1530273550680460,\n>> +  \"pid\": 107270,\n>> +  \"sid\": \"1530273550667800-107270\",\n>> +  \"command\": \"status\",\n>> +  \"argv\": [\n>> +    \"./git\",\n>> +    \"status\"\n>> +  ],\n>> +  \"result\": {\n>> +    \"exit_code\": 0,\n>> +    \"elapsed_core_us\": 12573,\n>> +    \"elapsed_total_us\": 12660\n>> +  },\n>> +  \"version\": {\n>> +    \"git\": \"2.18.0.rc0.83.gde7fb7c\",\n>> +    \"slog\": 0\n>> +  },\n>> +  \"config\": {\n>> +    \"slog\": {\n>> +      \"detail\": 0,\n>> +      \"timers\": 0,\n>> +      \"aux\": 0\n>> +    }\n>> +  }\n>> +}\n>> +\n>> +Both events fields describing the event name, the event time (in\n> \n> Maybe \"Both events have fields describing the event name...\"\n> \n>> +microseconds since the epoch), the OS process-id, a unique session-id\n>> +(described later), the normalized command name, and a vector of the\n>> +original command line arguments.\n>> +\n>> +The \"cmd_exit\" event additionally contains information about how the\n>> +process exited, the elapsed time, the version of git and the SLOG\n>> +format, and important SLOG configuration settings.\n>> +\n> \n> At first glance, the SLOG configuration settings seem out of place but \n> I'll read on to see why they are needed with every cmd_exit event...\n> \n\nEach git command process is independent. It just emits cmd_start,\ndetail, cmd_exit events for itself w/o knowing if a previous git\ncommand just wrote a cmd_exit event with those details. So I included\nthem in each cmd_exit event.\n\n\n>> +The fields in the \"cmd_start\" event are replicated in the \"cmd_exit\"\n>> +event.  This allows log file post-processors to operate in 2 modes:\n>> +\n>> +1. Just look at the \"cmd_exit\" events.  This us useful if you just\n>> +   want to analyze the command summary data.\n>> +\n>> +2. Look at the \"cmd_start\" and \"cmd_exit\" events as bracketing a time\n>> +   span and examine the detailed activity between.  For example, SLOG\n>> +   can optionally generate \"detail\" events when spawning child\n>> +   processes and those processes may themselves generate \"cmd_start\"\n>> +   and \"cmd_exit\" events.  The (top-level) \"cmd_start\" event serves as\n>> +   the starting bracket of all of that activity.\n>> +\n> \n> I'm assuming the sid is what will enable correlating the child process \n> events with the outer command?\n\nYes, the SID for a child git process contains the SID of its parent\ngit process.\n\n> \n>> +\n>> +Target Log File\n>> +===============\n>> +\n>> +SLOG writes events to a log file.  File logging works much like\n>> +GIT_TRACE where events are appended to a file on disk.\n>> +\n>> +Logging is enabled if the config variable \"slog.path\" is set to an\n>> +absolute pathname.\n>> +\n>> +As with GIT_TRACE, this file is local and private to the user's\n>> +system.  Log file management and rotation is beyond the scope of the\n>> +SLOG effort.\n>> +\n>> +Similarly, if a user wants to provide this data to a developer, they\n>> +must explicitly make these log files available; SLOG does not\n>> +broadcast any of this information.  It is up to the users of this\n>> +system to decide if any sensitive information should be sanitized, and\n>> +how to export the logs.\n>> +\n> \n> It's good to clarify this.\n> \n>> +\n>> +Comparison with GIT_TRACE\n>> +=========================\n>> +\n>> +SLOG is very similar to the existing GIT_TRACE[4] API because both\n>> +write event messages at various points during a command.  However,\n>> +there are some fundamental differences that warrant it being\n>> +considered a separate feature rather than just another\n>> +GIT_TRACE_:\n>> +\n> \n> But it does make me wonder if we need to keep both systems.  If there \n> are two, as a developer I need to know which I should use.  What is the \n> criteria I should use to decide between adding GIT_TRACE and SLOG \n> tracing?  It seems like it would be best if we could converge on a \n> single tracing model.\n> \n>> +1. GIT_TRACE events are unrelated, line-by-line logging.  SLOG has\n>> +   line-by-line events that show command progress and can serve as\n>> +   structured debug messages.  SLOG also supports accumulating summary\n>> +   data (such as timers) that are automatically added to the final\n>> +   `cmd_exit` event.\n>> +\n>> +2. GIT_TRACE events are unstructured free format printf-style messages\n>> +   which makes post-processing difficult.  SLOG events are written in\n>> +   JSON and can be easily parsed using Perl, Python, and other tools.\n>> +\n>> +3. SLOG uses a well-defined API to build SLOG events containing\n>> +   well-defined fields to make post-command analysis easier.\n>> +\n>> +4. It should be easier to filter/redact sensitive information from\n>> +   SLOG data than from free form data.\n>> +\n>> +5. GIT_TRACE events are controlled by one or more global environment\n>> +   variables which makes it awkward to selectively log some repos and\n>> +   not others.  SLOG events are controlled by a few configuration\n>> +   settings[5].  Users (or system administrators) can configure\n>> +   logging using repo-local or global config settings.\n>> +\n>> +6. GIT_TRACE events do not identify the git process.  This makes it\n>> +   difficult to associate all of events from a particular command.\n>> +   Each SLOG event contains a session id to allow all events for a\n>> +   command to be identified.\n>> +\n>> +7. Some git commands spawn child git commands.  GIT_TRACE has no\n>> +   mechanism to associate events from a child process with the parent\n>> +   process.  SLOG session ids allow child/parent relationships to be\n>> +   tracked (even if there is an intermediate /bin/sh process between\n>> +   them).\n>> +\n>> +8. GIT_TRACE supports logging to a file or stderr.  SLOG only logs to\n>> +   a file.\n>> +\n>> +9. Smashing SLOG into GIT_TRACE doesn't feel like a good fit.  The 2\n>> +   APIs share nothing other than the concept that they write logging\n>> +   data.\n>> +\n> \n> Is SLOG a superset of GIT_TRACE? If not, could it be?  While SLOG can't \n> be smashed into GIT_TRACE, can the functionality of GIT_TRACE be \n> subsumed by SLOG so that we can converge on a single tracing system?\n> \n> I'd like to see a design goal for this effort to be that we come up with \n> a single tracing mechanism that meets _all_ the requirements (including \n> those currently met by GIT_TRACE).\n\nIt would be good to consolidate them for the reasons you suggest.\nI initially tried adding SLOG into GIT_TRACE and it just didn't fit.\nI hesitated trying to convert GIT_TRACE because of the footprint of\nthe changes and what I have here is already large.\n\nLet me take another look and see.\n\n> \n>> +\n>> +[1] http://json.org/\n>> +[2] http://www.ietf.org/rfc/rfc7159.txt\n>> +[3] See UTF-8 limitations described in json-writer.h\n>> +[4] Documentation/technical/api-trace.txt\n>> +[5] See \"slog.*\" in Documentation/config.txt\n>> +[6] https://public-inbox.org/git/20180313004940.GG61720@google.com/t/\n>> +\n>> +\n>> +SLOG Format (V0)\n>> +================\n>> +\n>> +SLOG writes a series of events to the log target.  Each event is a\n>> +self-describing JSON object.\n>> +\n>> +    LF\n>> +    LF\n>> +    LF\n>> +    ...\n>> +\n>> +Each event record in the log file is an independent and complete JSON\n>> +object.  JSON parsers should process the file line-by-line rather than\n>> +trying to parse the entire file into a single object.\n>> +\n>> +    Note: It may be difficult for parsers to find record boundaries if\n>> +    pretty-printing is enabled, so it recommended that pretty-printing\n>> +    only be enabled for interactive debugging and analysis.\n>> +\n>> +Every contains the following fields (F1):\n>> +\n>> +    \"event\"       : \n>> +    \"clock_us\"    : \n>> +    \"pid\"         : \n>> +    \"sid\"         : \n>> +\n>> +    \"command\"     : \n>> +    \"sub_command\" : (optional)\n>> +\n>> + is one of \"cmd_start\", \"cmd_end\", or \"detail\".\n>> +\n>> + is the time of the event in microseconds since the epoch.\n>> +\n>> + is the process-id (from getpid()).\n>> +\n>> + is a session-id.  (Described later)\n>> +\n>> + is a (possibly normalized) command name.  This is\n>> +    usually taken from the cmd_struct[] table after git parses the\n>> +    command line and calls the appropriate cmd_() function.\n>> +    Having it in a top-level field saves post-processors from having\n>> +    to re-parse the command line to discover it.\n>> +\n>> + further qualifies the command.  This field is\n>> +    present for common commands that have multiple command modes.  For\n>> +    example, checkout can either change branches and do a full\n>> +    checkout or it can checkout (refresh) an individual file.  A\n>> +    post-processor wanting to compute percentiles for the time spent\n>> +    by branch-changing checkouts could easily filter out the\n>> +    individual file checkouts (and without having to re-parse the\n>> +    command line).\n>> +\n>> +    The set of sub_command values are command-specific and are not\n>> +    listed here.\n> \n> The sub-command definition seems a little squishy but I guess since you\n> have the entire set of command line arguments, it's really just a hint\n> as you could always drop back to looking at the arguments yourself.\n\nYes, it is a little squishy and I only added values for a few commands\nthat I was interested in. Others can be added later.\n\nWithout something like this, post-processing is difficult as it would\nneed reparse the command args and/or expand aliases to figure out what\nthe type of command -- for example, a branch-changing checkout. Having\nthis field lets me dump the log file into SQL and select just those\nrecords, for example.\n\nGranted, not strictly necessary to be inside git.exe, but it saves a\nlot of post-processing effort to recreate that information.\n\n\n> \n>> +\n>> +\"event\": \"cmd_start\"\n>> +-------------------\n>> +\n>> +The \"cmd_start\" event is emitted when git starts when cmd_main() is\n>> +called.  In addition to the F1 fields, it contains the following\n>> +fields (F2):\n>> +\n>> +    \"argv\"        : \n>> +\n>> + is an array of the original command line arguments given to the\n>> +    command (before git.c has a chance to remove the global options\n>> +    before the verb.\n>> +\n>> +\n>> +\"event\": \"cmd_exit\"\n>> +-------------------\n>> +\n>> +The \"cmd_exit\" event is emitted immediately before git exits (during\n>> +an atexit() routine).  It contains the F1 and F2 fields as described\n>> +above.  It also contains the the following fields (F3):\n>> +\n>> +    \"result.exit_code\"        : \n>> +    \"result.errors\"           : (optional)\n>> +    \"result.elapsed_core_us\"  : \n>> +    \"result.elapsed_total_us\" : \n>> +    \"result.signal\"           : (optional)\n>> +\n>> +    \"verion.git\"              : \n>> +    \"version.slog\"            : \n>> +\n>> +    \"config.slog.detail\"      : \n>> +    \"config.slog.timers\"      : \n>> +    \"config.slog.aux\"         : \n>> +    \"config.*.*\"              : (optional)\n>> +\n>> +    \"timers\"                  : (optional)\n>> +    \"aux\"                     : (optional)\n>> +\n>> +    \"child_summary\"           : (optional)\n>> +\n>> + is the value passed to exit() or returned from main().\n>> +\n>> + is an array of messages passed to the die()\n>> +    and error() functions.\n>> +\n>> + is the elapsed time from start until exit()\n>> +    was called or main() returned.\n>> +\n>> + is the elapsed time from start until the slog\n>> +    atexit routine was called.  This time will include any time\n>> +    required to shut down or wait for the pager to complete.\n>> +\n> \n> I wonder how valuable the difference is between these two and if we \n> could simply drop the \n> \n>> + is present if the command was stopped by a single,\n> \n> s/single/signal\n> \n>> +    such as a SIGPIPE when the pager is quit.\n>> +\n>> + is the git version number as reported by \"git version\".\n>> +\n>> + is the SLOG format version.\n>> +\n>> + are the values of the corresponding\n>> +    \"slog.{detail,timers,aux}\" config setting.  Since these values\n>> +    control optional SLOG features and filtering, these are present\n>> +    to help post-processors know if an expected event did not happen\n>> +    or was simply filtered out.  (Described later)\n>> +\n>> + is a place for developers to add additional\n>> +    important config settings to the log.  This is not intended as a\n>> +    dumping ground for all config settings, but rather only ones that\n>> +    might affect performance or allow A/B testing in production.\n>> +\n>> + is a structure of any SLOG timers used during the process.\n>> +    (Described later)\n>> +\n>> + is a structure of any \"aux data\" generated during the process.\n>> +    (Described later)\n>> +\n>> + is a structure summarizing child processes by class.\n>> +    (Described later)\n>> +\n>> +\n>> +\"event\": \"detail\" and config setting \"slog.detail\"\n>> +--------------------------------------------------\n>> +\n>> +The \"detail\" event is used to report progress and/or debug information\n>> +during a command.  It is a line-by-line (rather than summary) event.\n>> +Like GIT_TRACE_, detail events are classified by \"category\" and\n>> +may be included or omitted based on the \"slog.detail\" config setting.\n>> +\n>> +Here are 3 example \"detail\" events:\n>> +\n>> +{\n>> +  \"event\": \"detail\",\n>> +  \"clock_us\": 1530273485479387,\n>> +  \"pid\": 107253,\n>> +  \"sid\": \"1530273485473820-107253\",\n>> +  \"command\": \"status\",\n>> +  \"detail\": {\n>> +    \"category\": \"index\",\n>> +    \"label\": \"lazy_init_name_hash\",\n>> +    \"data\": {\n>> +      \"cache_nr\": 3269,\n>> +      \"elapsed_us\": 195,\n>> +      \"dir_count\": 0,\n>> +      \"dir_tablesize\": 4096,\n>> +      \"name_count\": 3269,\n>> +      \"name_tablesize\": 4096\n>> +    }\n>> +  }\n>> +}\n>> +{\n>> +  \"event\": \"detail\",\n>> +  \"clock_us\": 1530283184051338,\n>> +  \"pid\": 109679,\n>> +  \"sid\": \"1530283180782876-109679\",\n>> +  \"command\": \"fetch\",\n>> +  \"detail\": {\n>> +    \"category\": \"child\",\n>> +    \"label\": \"child_starting\",\n>> +    \"data\": {\n>> +      \"child_id\": 3,\n>> +      \"git_cmd\": true,\n>> +      \"use_shell\": false,\n>> +      \"is_interactive\": false,\n>> +      \"child_argv\": [\n>> +        \"gc\",\n>> +        \"--auto\"\n>> +      ]\n>> +    }\n>> +  }\n>> +}\n>> +{\n>> +  \"event\": \"detail\",\n>> +  \"clock_us\": 1530283184053158,\n>> +  \"pid\": 109679,\n>> +  \"sid\": \"1530283180782876-109679\",\n>> +  \"command\": \"fetch\",\n>> +  \"detail\": {\n>> +    \"category\": \"child\",\n>> +    \"label\": \"child_ended\",\n>> +    \"data\": {\n>> +      \"child_id\": 3,\n>> +      \"git_cmd\": true,\n>> +      \"use_shell\": false,\n>> +      \"is_interactive\": false,\n>> +      \"child_argv\": [\n>> +        \"gc\",\n>> +        \"--auto\"\n>> +      ],\n>> +      \"child_pid\": 109684,\n>> +      \"child_exit_code\": 0,\n>> +      \"child_elapsed_us\": 1819\n>> +    }\n>> +  }\n>> +}\n>> +\n>> +A detail event contains the common F1 described earlier.  It also\n>> +contains 2 fixed fields and 1 variable field:\n>> +\n>> +    \"detail.category\" : \n>> +    \"detail.label\"    : \n>> +    \"detail.data\"     : \n>> +\n>> + is the \"category\" name for the event.  This is\n>> +    similar to GIT_TRACE_.  In the example above we have 1\n>> +    \"index\" and 2 \"child\" category events.\n>> +\n>> +    If the config setting \"slog.detail\" is true or contains this\n>> +    category name, the event will be generated.  If \"slog.detail\"\n>> +    is false, no detail events will be generated.\n>> +\n>> +    $ git config slog.detail true\n>> +    $ git config slog.detail child,index,status\n>> +    $ git config slog.detail false\n>> +\n>> + is a descriptive label for the event.  It may be the\n>> +    name of a function or any meaningful value.\n>> +\n>> + is a JSON structure containing context-specific data for\n>> +    the event.  This replaces the need for printf-like trace messages.\n> \n> Hmm, couldn't this (a new \"Trace Detail Event) be used to help replace \n> the existing GIT_TRACE mechanism? I think one missing piece is a \n> formatting option other than \"pretty.\" Perhaps another field that is a \n> format string that can be used to give it a richer human readable output?\n\nMaybe. Let me take a look and see what that would look like.\n\n> \n> Overall this looks very robust and capable.  Clearly my biggest feedback \n> is that I'd like to see this be able to replace the existing GIT_TRACE \n> and GIT_TRACE_PERFORMANCE support.  Having two different mechanisms \n> seems unnecessarily complex and will increase the mental burden when \n> adding tracing.  It also doubles the code we need to \n> write/debug/document/support.  I'd hate to see callers of the tracing \n> code having to double up and including calls to both tracing mechanisms.\n> \n> I'm OK if this is a goal and migrating the existing calls to GIT_TRACE \n> are cleaned up over time.  It may be a nice intermediate step if the \n> existing macros could be re-implemented to sit on top of the new SLOG \n> infrastructure. This would certainly make it easier to migrate the code \n> base over time.\n> \n> \n\nThanks,\nJeff\n\n"},{"id":"356158","messageId":"20180821044724.GA219616@aiede.svl.corp.google.com","threadId":"48879","inReplyTo":"20180713165621.52017-2-git@jeffhostetler.com","subject":"Re: [PATCH v1 01/25] structured-logging: design document","fromName":"Jonathan Nieder","fromEmail":"jrnieder@gmail.com","sentAt":"2018-08-21T04:47:24Z","receivedAt":"2018-08-21T04:47:29Z","isPatch":true,"sender":{"key":"jrnieder@gmail.com","avatar":"https://avatars.githubusercontent.com/u/281595?v=4"},"body":"Hi,\n\nJeff Hostetler wrote:\n\n> Signed-off-by: Jeff Hostetler \n> ---\n> Documentation/technical/structured-logging.txt | 816 +++++++++++++++++++++++++\n> 1 file changed, 816 insertions(+)\n> create mode 100644 Documentation/technical/structured-logging.txt\n\nCan you add this to Documentation/Makefile as well, so that an HTML\nversion will appear once this is merged? See\nhttps://public-inbox.org/git/20180814222846.GG142615@aiede.svl.corp.google.com/\nfor an example.\n\n[...]\n> +++ b/Documentation/technical/structured-logging.txt\n> @@ -0,0 +1,816 @@\n> +Structured Logging\n> +==================\n> +\n> +Structured Logging (SLOG) is an optional feature to allow Git to\n> +generate structured log data for executed commands. This includes\n> +command line arguments, command run times, error codes and messages,\n> +child process information, time spent in various critical functions,\n> +and repository data-shape information. Data is written to a target\n> +log file in JSON[1,2,3] format.\n\nI like the idea of more structured logs for tracing, monitoring, and\ndiagnosis (see also\nhttps://research.google.com/archive/papers/dapper-2010-1.pdf on the\nsubject of tracing). My main focus in looking over this initial\ncontribution is\n\n 1. Is this something that could eventually merge with our other\n tracing APIs (e.g. trace_printf), or will they remain separate?\n\n 2. Is the API introduced here one that will be easy to work with\n and adapt? What will calling code that makes use of it look like?\n\n[...]\n> +Background (Git Merge 2018 Barcelona)\n> +=====================================\n> +\n> +Performance and/or error logging was discussed during the contributor's\n> +summit in Barcelona. Here are the relevant notes from the meeting\n> +minutes[6].\n> +\n> +> Performance misc (Ævar)\n> +> -----------------------\n> +> [...]\n> +> - central error reporting for git\n> +> - `git status` logging\n> +> - git config that collects data, pushes to known endpoint with `git push`\n> +> - pre_command and post_command hooks, for logs\n> +> - `gvfs diagnose` that looks at packfiles, etc\n[etc]\n\nI'm not sure what to make of this section. Is it a historical\nartifact, or should I consider it part of the design?\n\n[...]\n> +A Quick Example\n> +===============\n> +\n> +Note: JSON pretty-printing is enabled in all of the examples shown in\n> +this document. When pretty-printing is turned off, each event is\n> +written on a single line. Pretty-printing is intended for debugging.\n> +It should be turned off in production to make post-processing easier.\n> +\n> + $ git config slog.pretty \n> +\n> +Here is a quick example showing SLOG data for \"git status\". This\n> +example has all optional features turned off. It contains 2 events.\n\nThanks for the example! I'd also be interested in what the tracing\ncode looks like, since the API is the 'deepest' change involved (the\ntracing format can easily change later based on experience).\n\nMy initial reaction to the example trace is that it feels like an odd\ncompromise: on one hand it uses text (JSON) to be human-readable, and\non the other hand it is structured to be machine-readable. The JSON\nwriter isn't using a standard JSON serialization library so parsing\ndifficulties seem likely, and the output is noisy enough that reading\nit by hand is hard, too. That leads me to wish for a different\nformat, like protobuf (where the binary form is very concise and\nparseable, and the textual form is IMHO more readable than JSON).\n\nAll that said, this is just the first tracing output format and it's\neasy to make new ones later. It seems fine for that purpose.\n\n[...]\n> +Target Log File\n> +===============\n> +\n> +SLOG writes events to a log file. File logging works much like\n> +GIT_TRACE where events are appended to a file on disk.\n\nDoes it write with O_APPEND? Does it do anything to guard against\ninterleaved events --- e.g. are messages buffered and then written\nwith a single write() call?\n\n[...]\n> +Comparison with GIT_TRACE\n> +=========================\n> +\n> +SLOG is very similar to the existing GIT_TRACE[4] API because both\n> +write event messages at various points during a command. However,\n> +there are some fundamental differences that warrant it being\n> +considered a separate feature rather than just another\n> +GIT_TRACE_:\n\nThe natural question would be in the opposite direction: can and\nshould trace_printf be reimplemented on top of this feature?\n\n[...]\n> + \n> + \n\nnit: trailing whitespace (you can find these with \"git show --check\").\n\n[...]\n> +A session id (SID) is a cheap, unique-enough string to associate all\n> +of the events generated by a single process. A child git process inherits\n> +the SID of their parent git process and incorporates it into their SID.\n\nI wonder if we can structure events in a more hierarchical way to\navoid having to special-case the toplevel command in this way.\n\n[...]\n> + # The \"cmd_exit\" event includes the command result and elapsed\n> + # time and the various configuration settings. During the run\n> + # \"index\" category timers were placed around the do_read_index()\n> + # and \"preload()\" calls and various \"status\" category timers were\n> + # placed around the 3 major parts of the status computation.\n> + # Lastly, an \"index\" category \"aux\" data item was added to report\n> + # the size of the index.\n\nEspecially for tracing and monitoring applications, it would be\nhelpful if more of the information were emitted earlier instead of\nwaiting for exit. Especially if I am trying to trace the cause of a\nhanging command, information that is only printed at exit does not\nhelp me.\n\nThe main missing bit in this doc is a sketch of the API. Looking\nforward to finding that in the header. ;-)\n\nSorry for the slow review, and thanks for your thoughtful work.\n\nSincerely,\nJonathan\n"},{"id":"356159","messageId":"20180821044954.GB219616@aiede.svl.corp.google.com","threadId":"48879","inReplyTo":"20180713165621.52017-3-git@jeffhostetler.com","subject":"Re: [PATCH v1 02/25] structured-logging: add STRUCTURED_LOGGING=1 to Makefile","fromName":"Jonathan Nieder","fromEmail":"jrnieder@gmail.com","sentAt":"2018-08-21T04:49:54Z","receivedAt":"2018-08-21T04:49:58Z","isPatch":true,"sender":{"key":"jrnieder@gmail.com","avatar":"https://avatars.githubusercontent.com/u/281595?v=4"},"body":"git@jeffhostetler.com wrote:\n\n> From: Jeff Hostetler \n>\n> Teach the Makefile to take STRUCTURED_LOGGING=1 variable to\n> compile in/out structured logging feature.\n>\n> Signed-off-by: Jeff Hostetler \n> ---\n> Makefile | 8 ++++++++\n> structured-logging.c | 9 +++++++++\n> structured-logging.h | 13 +++++++++++++\n> 3 files changed, 30 insertions(+)\n> create mode 100644 structured-logging.c\n> create mode 100644 structured-logging.h\n\nThis should probably be squashed with a later patch (e.g., patch 3).\nWhen taken alone, it produces\n\n[...]\n> --- /dev/null\n> +++ b/structured-logging.c\n> @@ -0,0 +1,9 @@\n> +#if !defined(STRUCTURED_LOGGING)\n> +/*\n> + * Structured logging is not available.\n> + * Stub out all API routines.\n> + */\n> +\n> +#else\n> +\n> +#endif\n\nwhich is not idiomatic (for example, it's missing a #include of\ngit-compat-util.h, etc).\n\nThanks,\nJonathan\n"},{"id":"356160","messageId":"20180821050541.GC219616@aiede.svl.corp.google.com","threadId":"48879","inReplyTo":"20180713165621.52017-4-git@jeffhostetler.com","subject":"Re: [PATCH v1 03/25] structured-logging: add structured logging framework","fromName":"Jonathan Nieder","fromEmail":"jrnieder@gmail.com","sentAt":"2018-08-21T05:05:41Z","receivedAt":"2018-08-21T05:05:46Z","isPatch":true,"sender":{"key":"jrnieder@gmail.com","avatar":"https://avatars.githubusercontent.com/u/281595?v=4"},"body":"Jeff Hostetler wrote:\n\n[...]\n> --- a/compat/mingw.h\n> +++ b/compat/mingw.h\n> @@ -144,8 +144,15 @@ static inline int fcntl(int fd, int cmd, ...)\n> \terrno = EINVAL;\n> \treturn -1;\n> }\n> +\n> /* bash cannot reliably detect negative return codes as failure */\n> +#if defined(STRUCTURED_LOGGING)\n\nGit usually spells this as #ifdef.\n\n> +#include \"structured-logging.h\"\n> +#define exit(code) exit(strlog_exit_code((code) & 0xff))\n> +#else\n> #define exit(code) exit((code) & 0xff)\n> +#endif\n\nThis is hard to follow, since it only makes sense in combination with\nthe corresponding code in git-compat-util.h. Can they be defined\ntogether? If not, can they have comments to make it easier to know to\nedit one too when editing the other?\n\n[...]\n> --- a/git-compat-util.h\n> +++ b/git-compat-util.h\n> @@ -1239,4 +1239,13 @@ extern void unleak_memory(const void *ptr, size_t len);\n> #define UNLEAK(var) do {} while (0)\n> #endif\n> \n> +#include \"structured-logging.h\"\n\nIs this #include needed? Usually git-compat-util.h only defines C\nstandard library functions or utilities that are used everywhere.\n\n[...]\n> --- a/git.c\n> +++ b/git.c\n[...]\n> @@ -700,7 +701,7 @@ static int run_argv(int *argcp, const char ***argv)\n> \treturn done_alias;\n> }\n> \n> -int cmd_main(int argc, const char **argv)\n> +static int real_cmd_main(int argc, const char **argv)\n> {\n> \tconst char *cmd;\n> \tint done_help = 0;\n> @@ -779,3 +780,8 @@ int cmd_main(int argc, const char **argv)\n> \n> \treturn 1;\n> }\n> +\n> +int cmd_main(int argc, const char **argv)\n> +{\n> +\treturn slog_wrap_main(real_cmd_main, argc, argv);\n> +}\n\nCan real_cmd_main get a different name, describing what it does?\n\n[...]\n> --- a/structured-logging.c\n> +++ b/structured-logging.c\n> @@ -1,3 +1,10 @@\n[...]\n> +static uint64_t my__start_time;\n> +static uint64_t my__exit_time;\n> +static int my__is_config_loaded;\n> +static int my__is_enabled;\n> +static int my__is_pretty;\n> +static int my__signal;\n> +static int my__exit_code;\n> +static int my__pid;\n> +static int my__wrote_start_event;\n> +static int my__log_fd = -1;\n\nPlease don't use this my__ notation. The inconsistency with the rest\nof Git makes the code feel out of place and provides an impediment to\nsmooth reading.\n\n[...]\n> +static void emit_start_event(void)\n> +{\n> +\tstruct json_writer jw = JSON_WRITER_INIT;\n> +\n> +\t/* build \"cmd_start\" event message */\n> +\tjw_object_begin(&jw, my__is_pretty);\n> +\t{\n> +\t\tjw_object_string(&jw, \"event\", \"cmd_start\");\n> +\t\tjw_object_intmax(&jw, \"clock_us\", (intmax_t)my__start_time);\n> +\t\tjw_object_intmax(&jw, \"pid\", (intmax_t)my__pid);\n\nThe use of blocks here is unexpected and makes me wonder what kind of\nmacro wizardry is going on. Perhaps this is idiomatic for the\njson-writer API; if so, can you add an example to json-writer.h to\nhelp the next surprised reader?\n\nThat said, I think\n\n\tjson_object_begin(&jw, ...);\n\n\tjson_object_string(...\n\tjson_object_int(...\n\t...\n\n\tjson_object_begin_inline_array(&jw, \"argv\");\n\tfor (k = 0; k < argv.argc; k++)\n\t\tjson_object_string(...\n\tjson_object_end(&jw);\n\n\tjson_object_end(&jw);\n\nis still readable and less unexpected.\n\n[...]\n> +static void emit_exit_event(void)\n> +{\n> +\tstruct json_writer jw = JSON_WRITER_INIT;\n> +\tuint64_t atexit_time = getnanotime() / 1000;\n> +\n> +\t/* close unterminated forms */\n\nWhat are unterminated forms?\n\n> +\tif (my__errors.json.len)\n> +\t\tjw_end(&my__errors);\n[...]\n> +int slog_default_config(const char *key, const char *value)\n> +{\n> +\tconst char *sub;\n> +\n> +\t/*\n> +\t * git_default_config() calls slog_default_config() with \"slog.*\"\n> +\t * k/v pairs. git_default_config() MAY or MAY NOT be called when\n> +\t * cmd_() calls git_config().\n\nNo need to shout.\n\n[...]\n> +/*\n> + * If cmd_() did not cause slog_default_config() to be called\n> + * during git_config(), we try to lookup our config settings the first\n> + * time we actually need them.\n> + *\n> + * (We do this rather than using read_early_config() at initialization\n> + * because we want any \"-c key=value\" arguments to be included.)\n> + */\n\nWhich function is initialization referring to here?\n\nLazy loading in order to guarantee loading after a different subsystem\nsounds a bit fragile, so I wonder if we can make the sequencing more\nexplicit.\n\nStopping here. I still like where this is going, but some aspects of\nthe coding style are making it hard to see the forest for the trees.\nPerhaps some more details about API in the design doc would help.\n\nThanks and hope that helps,\nJonathan\n"},{"id":"356712","messageId":"xmqqd0u2gzma.fsf@gitster-ct.c.googlers.com","threadId":"48879","inReplyTo":"20180713165621.52017-1-git@jeffhostetler.com","subject":"Re: [PATCH v1 00/25] RFC: structured logging","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2018-08-28T17:38:53Z","receivedAt":"2018-08-28T17:38:59Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"git@jeffhostetler.com writes:\n\n> From: Jeff Hostetler \n>\n> This RFC patch series adds structured logging to git. The motivation,\n> ...\n>\n> Jeff Hostetler (25):\n> structured-logging: design document\n> structured-logging: add STRUCTURED_LOGGING=1 to Makefile\n> structured-logging: add structured logging framework\n> structured-logging: add session-id to log events\n> structured-logging: set sub_command field for branch command\n> structured-logging: set sub_command field for checkout command\n> structured-logging: t0420 basic tests\n> structured-logging: add detail-event facility\n> structured-logging: add detail-event for lazy_init_name_hash\n> structured-logging: add timer facility\n> structured-logging: add timer around do_read_index\n> structured-logging: add timer around do_write_index\n> structured-logging: add timer around wt-status functions\n> structured-logging: add timer around preload_index\n> structured-logging: t0420 tests for timers\n> structured-logging: add aux-data facility\n> structured-logging: add aux-data for index size\n> structured-logging: add aux-data for size of sparse-checkout file\n> structured-logging: t0420 tests for aux-data\n> structured-logging: add structured logging to remote-curl\n> structured-logging: add detail-events for child processes\n> structured-logging: add child process classification\n> structured-logging: t0420 tests for child process detail events\n> structured-logging: t0420 tests for interacitve child_summary\n> structured-logging: add config data facility\n\n\nI noticed that Travis job has been failing with a trivially fixable\nfailure, so I'll push out today's 'pu' with the attached applied on\ntop. This may become unapplicable to the code when issues raised in\nrecent reviews addressed, though.\n\n structured-logging.c | 6 ++----\n 1 file changed, 2 insertions(+), 4 deletions(-)\n\ndiff --git a/structured-logging.c b/structured-logging.c\nindex 0e3f79ee48..78abcd2e59 100644\n--- a/structured-logging.c\n+++ b/structured-logging.c\n@@ -593,8 +593,7 @@ void slog_set_command_name(const char *command_name)\n \t * the cmd_() and/or it may be too early to force a\n \t * lazy load.\n \t */\n-\tif (my__command_name)\n-\t\tfree(my__command_name);\n+\tfree(my__command_name);\n \tmy__command_name = xstrdup(command_name);\n }\n \n@@ -606,8 +605,7 @@ void slog_set_sub_command_name(const char *sub_command_name)\n \t * the cmd_() and/or it may be too early to force a\n \t * lazy load.\n \t */\n-\tif (my__sub_command_name)\n-\t\tfree(my__sub_command_name);\n+\tfree(my__sub_command_name);\n \tmy__sub_command_name = xstrdup(sub_command_name);\n }\n \n-- \n2.19.0-rc0-48-gb9dfa238d5\n\n\n"},{"id":"356716","messageId":"4bc19d36-1242-9e83-a9ed-ed58a681b499@jeffhostetler.com","threadId":"48879","inReplyTo":"xmqqd0u2gzma.fsf@gitster-ct.c.googlers.com","subject":"Re: [PATCH v1 00/25] RFC: structured logging","fromName":"Jeff Hostetler","fromEmail":"git@jeffhostetler.com","sentAt":"2018-08-28T18:47:14Z","receivedAt":"2018-08-28T18:47:18Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"\n\nOn 8/28/2018 1:38 PM, Junio C Hamano wrote:\n> git@jeffhostetler.com writes:\n> \n>> From: Jeff Hostetler \n>>\n>> This RFC patch series adds structured logging to git. The motivation,\n>> ...\n>>\n>> Jeff Hostetler (25):\n>> structured-logging: design document\n>> structured-logging: add STRUCTURED_LOGGING=1 to Makefile\n>> structured-logging: add structured logging framework\n>> structured-logging: add session-id to log events\n>> structured-logging: set sub_command field for branch command\n>> structured-logging: set sub_command field for checkout command\n>> structured-logging: t0420 basic tests\n>> structured-logging: add detail-event facility\n>> structured-logging: add detail-event for lazy_init_name_hash\n>> structured-logging: add timer facility\n>> structured-logging: add timer around do_read_index\n>> structured-logging: add timer around do_write_index\n>> structured-logging: add timer around wt-status functions\n>> structured-logging: add timer around preload_index\n>> structured-logging: t0420 tests for timers\n>> structured-logging: add aux-data facility\n>> structured-logging: add aux-data for index size\n>> structured-logging: add aux-data for size of sparse-checkout file\n>> structured-logging: t0420 tests for aux-data\n>> structured-logging: add structured logging to remote-curl\n>> structured-logging: add detail-events for child processes\n>> structured-logging: add child process classification\n>> structured-logging: t0420 tests for child process detail events\n>> structured-logging: t0420 tests for interacitve child_summary\n>> structured-logging: add config data facility\n> \n> \n> I noticed that Travis job has been failing with a trivially fixable\n> failure, so I'll push out today's 'pu' with the attached applied on\n> top. This may become unapplicable to the code when issues raised in\n> recent reviews addressed, though.\n> \n> structured-logging.c | 6 ++----\n> 1 file changed, 2 insertions(+), 4 deletions(-)\n> \n> diff --git a/structured-logging.c b/structured-logging.c\n> index 0e3f79ee48..78abcd2e59 100644\n> --- a/structured-logging.c\n> +++ b/structured-logging.c\n> @@ -593,8 +593,7 @@ void slog_set_command_name(const char *command_name)\n> \t * the cmd_() and/or it may be too early to force a\n> \t * lazy load.\n> \t */\n> -\tif (my__command_name)\n> -\t\tfree(my__command_name);\n> +\tfree(my__command_name);\n> \tmy__command_name = xstrdup(command_name);\n> }\n> \n> @@ -606,8 +605,7 @@ void slog_set_sub_command_name(const char *sub_command_name)\n> \t * the cmd_() and/or it may be too early to force a\n> \t * lazy load.\n> \t */\n> -\tif (my__sub_command_name)\n> -\t\tfree(my__sub_command_name);\n> +\tfree(my__sub_command_name);\n> \tmy__sub_command_name = xstrdup(sub_command_name);\n> }\n> \n> \n\nSorry about that.\n\nLet me withdraw the current series. I'm working on a new version that\naddresses the comments on the mailing list. It combines my logging\nwith a variation on the nested perf logging that Duy suggested and\nthe consolidation that you were talking about last week.\n\nJeff\n\n"}]}