{"action":"created","issue":{"url":"https://api.github.com/repos/systemd/systemd/issues/2280","repository_url":"https://api.github.com/repos/systemd/systemd","labels_url":"https://api.github.com/repos/systemd/systemd/issues/2280/labels{/name}","comments_url":"https://api.github.com/repos/systemd/systemd/issues/2280/comments","events_url":"https://api.github.com/repos/systemd/systemd/issues/2280/events","html_url":"https://github.com/systemd/systemd/pull/2280","id":125255009,"number":2280,"title":"journal: refactor process metadata interrogation","user":{"login":"vcaputo","id":1452963,"avatar_url":"https://avatars.githubusercontent.com/u/1452963?v=3","gravatar_id":"","url":"https://api.github.com/users/vcaputo","html_url":"https://github.com/vcaputo","followers_url":"https://api.github.com/users/vcaputo/followers","following_url":"https://api.github.com/users/vcaputo/following{/other_user}","gists_url":"https://api.github.com/users/vcaputo/gists{/gist_id}","starred_url":"https://api.github.com/users/vcaputo/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/vcaputo/subscriptions","organizations_url":"https://api.github.com/users/vcaputo/orgs","repos_url":"https://api.github.com/users/vcaputo/repos","events_url":"https://api.github.com/users/vcaputo/events{/privacy}","received_events_url":"https://api.github.com/users/vcaputo/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/systemd/systemd/labels/journal","name":"journal","color":"d4c5f9"},{"url":"https://api.github.com/repos/systemd/systemd/labels/reviewed/needs-rework","name":"reviewed/needs-rework","color":"eb6420"}],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":19,"created_at":"2016-01-06T20:19:16Z","updated_at":"2016-06-02T12:36:57Z","closed_at":null,"pull_request":{"url":"https://api.github.com/repos/systemd/systemd/pulls/2280","html_url":"https://github.com/systemd/systemd/pull/2280","diff_url":"https://github.com/systemd/systemd/pull/2280.diff","patch_url":"https://github.com/systemd/systemd/pull/2280.patch"},"body":"Currently systemd-journald interrogates the log-producing process on a\r\nper-dispatched-message basis, which ultimately results in doing\r\nsignificant work for every line logged even within a single received\r\nbuffer where this information should be identical from the other\r\nmessages dispatched from the same buffer.\r\n\r\nThis commit rearranges things so we cache and reuse the metadata across\r\nmultiple messages when possible, refreshing on buffer boundaries, and\r\nusing the cached information should refreshing fail (common when\r\nprocessing a message produced by a now-exited process, like when a\r\ndaemon errors and exits).\r\n\r\nIn addition to enabling caching and reuse of the interrogated state,\r\nthis also changes the way the appended entry is being assembled to\r\nrequire fewer allocations and copies per message.\r\n\r\nThe common OBJECT_PID == _PID case has also been optimized to simply\r\nreuse the cached metadata retrieved for _PID.\r\n\r\nThe current implementation of interrogating the process on every message\r\nis arguably less correct than this more efficient version as well.  The\r\nmessages by the time we interrogate the log-producing process are always\r\nfrom the past, the best we can do is to interrogate once at the time we\r\nprocess the buffer, on behalf of the entire buffer, and reuse that\r\nmetadata as if it were current for all messages contained therein.\r\nRepeatedly interrogating for every message querying the instantaneous\r\nprocess state for data associated with a message from the past is less\r\nlikely to be accurate.\r\n\r\nIn order to make this all work correctly journal_file_append_entry()\r\nneeded modification to support scatter-gather IO within the individual\r\nentry items, introducing a new JournalEntryItem type for describing the\r\nentry.\r\n\r\nPreviously journal_file_append_entry() used the struct iovec to represent\r\neach \"KEY=VALUE\" item of the entry being appended, preventing scattered\r\nbuffers from representing the individual items.\r\n\r\nThe new interface allows performing fewer allocations and copies in\r\nconstructing the appended journal entries by using a static array of\r\nthe constant \"KEY=\" strings which a per-item iovec may simply reference,\r\nand simply referencing the discrete \"VALUE\" right hand side from the\r\nmetadata cache in the subsequent iovec for the item.  This is also what\r\nenables the OBJECT_PID == _PID metadata reuse optimization mentioned\r\nabove; the VALUE side of multiple items may simply reference the same\r\nvalue within the metadata cache.\r\n\r\nSome data:\r\n```\r\n $ # journald-native (a-la libsystemd), ephemeral processes\r\n $ time {\r\n     for ((i=0; i < 1000; i++)); do\r\n       dd if=/dev/urandom bs=8k count=1 | od -x | systemd-cat\r\n     done\r\n   } >& /dev/null\r\n\r\n  Before:\r\n   real    0m11.938s\r\n   user    0m1.788s\r\n   sys     0m2.153s\r\n\r\n   real    0m11.989s\r\n   user    0m1.846s\r\n   sys     0m2.130s\r\n\r\n   real    0m12.012s\r\n   user    0m1.802s\r\n   sys     0m2.176s\r\n\r\n  Now:\r\n   real    0m7.937s\r\n   user    0m1.801s\r\n   sys     0m2.062s\r\n\r\n   real    0m8.094s\r\n   user    0m1.685s\r\n   sys     0m2.277s\r\n\r\n   real    0m8.114s\r\n   user    0m1.751s\r\n   sys     0m2.152s\r\n\r\n---\r\n\r\n $ # journald-native (a-la libsystemd), persistent process\r\n $ dd if=/dev/urandom bs=8k | od -x | systemd-cat\r\n\r\n  Before:\r\n   1000+0 records in\r\n   1000+0 records out\r\n   8192000 bytes (8.2 MB) copied, 7.28229 s, 1.1 MB/s\r\n   1000+0 records in\r\n   1000+0 records out\r\n   8192000 bytes (8.2 MB) copied, 9.78265 s, 837 kB/s\r\n   1000+0 records in\r\n   1000+0 records out\r\n   8192000 bytes (8.2 MB) copied, 8.17331 s, 1.0 MB/s\r\n\r\n  Now:\r\n   1000+0 records in\r\n   1000+0 records out\r\n   8192000 bytes (8.2 MB) copied, 1.3507 s, 6.1 MB/s\r\n   1000+0 records in\r\n   1000+0 records out\r\n   8192000 bytes (8.2 MB) copied, 1.13135 s, 7.2 MB/s\r\n   1000+0 records in\r\n   1000+0 records out\r\n   8192000 bytes (8.2 MB) copied, 1.17473 s, 7.0 MB/s\r\n\r\n---\r\n\r\n $ # journald-stream (a-la systemd services)\r\n $ cat >> noise.sh <<EOF\r\n #!/bin/bash\r\n dd if=/dev/urandom bs=8k count=1000 2>/tmp/foo | od -x\r\n EOF\r\n $ chmod +x noise.sh\r\n $ tail -F /tmp/foo &\r\n $ systemd-run ./noise.sh\r\n\r\n  Before:\r\n   1000+0 records in\r\n   1000+0 records out\r\n   8192000 bytes (8.2 MB) copied, 4.35375 s, 1.9 MB/s\r\n   1000+0 records in\r\n   1000+0 records out\r\n   8192000 bytes (8.2 MB) copied, 4.56279 s, 1.8 MB/s\r\n   1000+0 records in\r\n   1000+0 records out\r\n   8192000 bytes (8.2 MB) copied, 9.26128 s, 885 kB/s\r\n\r\n  Now:\r\n   1000+0 records in\r\n   1000+0 records out\r\n   8192000 bytes (8.2 MB) copied, 1.38334 s, 5.9 MB/s\r\n   1000+0 records in\r\n   1000+0 records out\r\n   8192000 bytes (8.2 MB) copied, 1.14587 s, 7.1 MB/s\r\n   1000+0 records in\r\n   1000+0 records out\r\n   8192000 bytes (8.2 MB) copied, 1.40992 s, 5.8 MB/s\r\n\r\n---\r\n\r\n $ # service's farewell messages lossy metadata\r\n $ gcc -x c -pipe -O2 -s -o sigh - <<EOF\r\n #include <unistd.h>\r\n int main(int argc, const char *argv[]) {\r\n         write(1, \"sleeping 5s\\n\", 12);\r\n         sleep(5);\r\n         write(1, \"farewell\\n\", 9);\r\n         return 0;\r\n }\r\n EOF\r\n $ journalctl --follow --all --output=verbose --identifier=sigh &\r\n $ systemd-run ./sigh\r\n $ dd if=/dev/urandom bs=8k | od -x | systemd-cat\r\n $ # sigh starts before dd, dd spams journald before farewell occurs, delaying\r\n $ # journald's servicing of farewell to race with sigh's exit.\r\n $ # Now we'll at least have as much metadata after exit as we ever did for any\r\n $ # previous log message on the stream.\r\n\r\n  Before:\r\n   Wed 2016-01-06 16:55:45.649644 UTC [...\r\n       _TRANSPORT=stdout\r\n       PRIORITY=6\r\n       _UID=0\r\n       _GID=0\r\n       _SELINUX_CONTEXT=system_u:system_r:kernel_t:s0\r\n       _BOOT_ID=9fd04fe784a340d5956d8c1db921c31b\r\n       _MACHINE_ID=7e967d2a1b3740f18722f903e0ccecfd\r\n       _HOSTNAME=coreos_developer_qemu-884-0-0-20\r\n       SYSLOG_FACILITY=3\r\n       SYSLOG_IDENTIFIER=sigh\r\n       MESSAGE=sleeping 5s\r\n       _CAP_EFFECTIVE=3fffffffff\r\n       _PID=19979\r\n       _COMM=sigh\r\n       _EXE=/tmp/sigh\r\n       _CMDLINE=/tmp/./sigh\r\n       _SYSTEMD_CGROUP=/system.slice/run-19978.service\r\n       _SYSTEMD_UNIT=run-19978.service\r\n       _SYSTEMD_SLICE=system.slice\r\n   Wed 2016-01-06 16:55:50.649851 UTC [...\r\n       _TRANSPORT=stdout\r\n       PRIORITY=6\r\n       _UID=0\r\n       _GID=0\r\n       _SELINUX_CONTEXT=system_u:system_r:kernel_t:s0\r\n       _BOOT_ID=9fd04fe784a340d5956d8c1db921c31b\r\n       _MACHINE_ID=7e967d2a1b3740f18722f903e0ccecfd\r\n       _HOSTNAME=coreos_developer_qemu-884-0-0-20\r\n       SYSLOG_FACILITY=3\r\n       SYSLOG_IDENTIFIER=sigh\r\n       MESSAGE=farewell\r\n       _CAP_EFFECTIVE=3fffffffff\r\n       _PID=19979\r\n       _COMM=sigh\r\n       _SYSTEMD_UNIT=run-19978.service\r\n\r\n  Now:\r\n   Wed 2016-01-06 16:57:19.857615 UTC [...\r\n       _TRANSPORT=stdout\r\n       PRIORITY=6\r\n       _BOOT_ID=9fd04fe784a340d5956d8c1db921c31b\r\n       _MACHINE_ID=7e967d2a1b3740f18722f903e0ccecfd\r\n       _HOSTNAME=coreos_developer_qemu-884-0-0-20\r\n       SYSLOG_FACILITY=3\r\n       _UID=0\r\n       _GID=0\r\n       _SYSTEMD_SLICE=system.slice\r\n       _SELINUX_CONTEXT=system_u:system_r:kernel_t:s0\r\n       _CAP_EFFECTIVE=3fffffffff\r\n       SYSLOG_IDENTIFIER=sigh\r\n       MESSAGE=sleeping 5s\r\n       _PID=19995\r\n       _COMM=sigh\r\n       _EXE=/tmp/sigh\r\n       _CMDLINE=/tmp/./sigh\r\n       _SYSTEMD_CGROUP=/system.slice/run-19994.service\r\n       _SYSTEMD_UNIT=run-19994.service\r\n   Wed 2016-01-06 16:57:24.860611 UTC [...\r\n       _TRANSPORT=stdout\r\n       PRIORITY=6\r\n       _BOOT_ID=9fd04fe784a340d5956d8c1db921c31b\r\n       _MACHINE_ID=7e967d2a1b3740f18722f903e0ccecfd\r\n       _HOSTNAME=coreos_developer_qemu-884-0-0-20\r\n       SYSLOG_FACILITY=3\r\n       _UID=0\r\n       _GID=0\r\n       _SYSTEMD_SLICE=system.slice\r\n       _SELINUX_CONTEXT=system_u:system_r:kernel_t:s0\r\n       _CAP_EFFECTIVE=3fffffffff\r\n       SYSLOG_IDENTIFIER=sigh\r\n       _PID=19995\r\n       _COMM=sigh\r\n       _EXE=/tmp/sigh\r\n       _CMDLINE=/tmp/./sigh\r\n       _SYSTEMD_CGROUP=/system.slice/run-19994.service\r\n       _SYSTEMD_UNIT=run-19994.service\r\n       MESSAGE=farewell\r\n\r\n---\r\n\r\n $ # no journald, ideal for reference\r\n $ dd if=/dev/urandom bs=8k count=1000 | od -x > /dev/null\r\n 1000+0 records in\r\n 1000+0 records out\r\n 8192000 bytes (8.2 MB) copied, 1.2545 s, 6.5 MB/s\r\n 1000+0 records in\r\n 1000+0 records out\r\n 8192000 bytes (8.2 MB) copied, 1.00709 s, 8.1 MB/s\r\n 1000+0 records in\r\n 1000+0 records out\r\n 8192000 bytes (8.2 MB) copied, 1.05836 s, 7.7 MB/s\r\n```"},"comment":{"url":"https://api.github.com/repos/systemd/systemd/issues/comments/223278561","html_url":"https://github.com/systemd/systemd/pull/2280#issuecomment-223278561","issue_url":"https://api.github.com/repos/systemd/systemd/issues/2280","id":223278561,"user":{"login":"gdamjan","id":81654,"avatar_url":"https://avatars.githubusercontent.com/u/81654?v=3","gravatar_id":"","url":"https://api.github.com/users/gdamjan","html_url":"https://github.com/gdamjan","followers_url":"https://api.github.com/users/gdamjan/followers","following_url":"https://api.github.com/users/gdamjan/following{/other_user}","gists_url":"https://api.github.com/users/gdamjan/gists{/gist_id}","starred_url":"https://api.github.com/users/gdamjan/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/gdamjan/subscriptions","organizations_url":"https://api.github.com/users/gdamjan/orgs","repos_url":"https://api.github.com/users/gdamjan/repos","events_url":"https://api.github.com/users/gdamjan/events{/privacy}","received_events_url":"https://api.github.com/users/gdamjan/received_events","type":"User","site_admin":false},"created_at":"2016-06-02T12:36:57Z","updated_at":"2016-06-02T12:36:57Z","body":"Why doesn't systemd inform the journal about the service that is going to use the logging socket before even starting the service? \r\nThen the journal would know exactly what to tag the message with and never have to interrogate the system about it."}}
{"actor":{"display_login":"gdamjan"}}