{"thread":{"id":"58231","subject":"fsmonitor: perpetual trivial response","startedAt":"2022-07-27T20:03:50Z","lastAt":"2022-08-02T13:54:36Z","messageCount":4,"participants":["Eric D","Johannes Schindelin","Jeff Hostetler"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"460035","messageId":"CAMxJVdH6=dP7vwruSnKFVTT4ZgygLK_2fu5TKoRia+WyMzATXA@mail.gmail.com","threadId":"58231","inReplyTo":null,"subject":"fsmonitor: perpetual trivial response","fromName":"Eric D","fromEmail":"eric.decosta@gmail.com","sentAt":"2022-07-27T20:03:34Z","receivedAt":"2022-07-27T20:03:50Z","isPatch":false,"sender":{"key":"eric.decosta@gmail.com","avatar":null},"body":"fsmonitor daemon was started in the background (i.e. git\nfsmonitor--daemon start) so I could enable trace2 logging.\n\n15:36:37.860862 ...n/fsmonitor--daemon.c:969 | d1 | th01:ipc-server\n      | region_enter | r1  | 124.965540 |           | fsmonitor    |\nlabel:handle_client\n15:36:37.860862 ...n/fsmonitor--daemon.c:970 | d1 | th01:ipc-server\n      | data         | r1  | 124.965809 |  0.000269 | fsmonitor    |\n..request:1658950597810367000\n15:36:37.860862 ...n/fsmonitor--daemon.c:786 | d1 | th01:ipc-server\n      | data         | r1  | 124.965892 |  0.000352 | fsmonitor    |\n..response/token:builtin:0.12336.20220727T193432.938608Z:0\n15:36:37.860862 ...n/fsmonitor--daemon.c:822 | d1 | th01:ipc-server\n      | data         | r1  | 124.965969 |  0.000429 | fsmonitor    |\n..response/trivial:1\n15:36:37.860862 ...n/fsmonitor--daemon.c:974 | d1 | th01:ipc-server\n      | region_leave | r1  | 124.966000 |  0.000460 | fsmonitor    |\nlabel:handle_client\n15:38:40.079662 ...n/fsmonitor--daemon.c:969 | d1 | th02:ipc-server\n      | region_enter | r1  | 247.186960 |           | fsmonitor    |\nlabel:handle_client\n15:38:40.079662 ...n/fsmonitor--daemon.c:970 | d1 | th02:ipc-server\n      | data         | r1  | 247.187067 |  0.000107 | fsmonitor    |\n..request:1658950720017776200\n15:38:40.079662 ...n/fsmonitor--daemon.c:786 | d1 | th02:ipc-server\n      | data         | r1  | 247.187328 |  0.000368 | fsmonitor    |\n..response/token:builtin:0.12336.20220727T193432.938608Z:0\n15:38:40.079662 ...n/fsmonitor--daemon.c:822 | d1 | th02:ipc-server\n      | data         | r1  | 247.187448 |  0.000488 | fsmonitor    |\n..response/trivial:1\n15:38:40.079662 ...n/fsmonitor--daemon.c:974 | d1 | th02:ipc-server\n      | region_leave | r1  | 247.187491 |  0.000531 | fsmonitor    |\nlabel:handle_client\n15:42:14.719673 ...n/fsmonitor--daemon.c:969 | d1 | th03:ipc-server\n      | region_enter | r1  | 461.821373 |           | fsmonitor    |\nlabel:handle_client\n15:42:14.719673 ...n/fsmonitor--daemon.c:970 | d1 | th03:ipc-server\n      | data         | r1  | 461.821429 |  0.000056 | fsmonitor    |\n..request:1658950934652816400\n15:42:14.719673 ...n/fsmonitor--daemon.c:786 | d1 | th03:ipc-server\n      | data         | r1  | 461.821467 |  0.000094 | fsmonitor    |\n..response/token:builtin:0.12336.20220727T193432.938608Z:0\n15:42:14.719673 ...n/fsmonitor--daemon.c:822 | d1 | th03:ipc-server\n      | data         | r1  | 461.821486 |  0.000113 | fsmonitor    |\n..response/trivial:1\n15:42:14.719673 ...n/fsmonitor--daemon.c:974 | d1 | th03:ipc-server\n      | region_leave | r1  | 461.821497 |  0.000124 | fsmonitor    |\nlabel:handle_client\n\nNote that this is a slightly hacked build of mine where I disabled the\ncheck for network filesystems. I also added some additional logging\nthat tells me that the query is successful, it's just that the\nresponse is trivial. The sandbox I am using is on the network and\nbeing accessed from my Windows VM.\n\n-Eric\n"},{"id":"460069","messageId":"840r6312-3r19-n087-68s1-rpo1n9869osn@tzk.qr","threadId":"58231","inReplyTo":"CAMxJVdH6=dP7vwruSnKFVTT4ZgygLK_2fu5TKoRia+WyMzATXA@mail.gmail.com","subject":"Re: fsmonitor: perpetual trivial response","fromName":"Johannes Schindelin","fromEmail":"johannes.schindelin@gmx.de","sentAt":"2022-07-28T13:48:36Z","receivedAt":"2022-07-28T13:48:50Z","isPatch":false,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"Hi Eric,\n\nOn Wed, 27 Jul 2022, Eric D wrote:\n\n> fsmonitor daemon was started in the background (i.e. git\n> fsmonitor--daemon start) so I could enable trace2 logging.\n>\n> 15:36:37.860862 ...n/fsmonitor--daemon.c:969 | d1 | th01:ipc-server\n>       | region_enter | r1  | 124.965540 |           | fsmonitor    |\n> label:handle_client\n> 15:36:37.860862 ...n/fsmonitor--daemon.c:970 | d1 | th01:ipc-server\n>       | data         | r1  | 124.965809 |  0.000269 | fsmonitor    |\n> ..request:1658950597810367000\n> 15:36:37.860862 ...n/fsmonitor--daemon.c:786 | d1 | th01:ipc-server\n>       | data         | r1  | 124.965892 |  0.000352 | fsmonitor    |\n> ..response/token:builtin:0.12336.20220727T193432.938608Z:0\n> 15:36:37.860862 ...n/fsmonitor--daemon.c:822 | d1 | th01:ipc-server\n>       | data         | r1  | 124.965969 |  0.000429 | fsmonitor    |\n> ..response/trivial:1\n> 15:36:37.860862 ...n/fsmonitor--daemon.c:974 | d1 | th01:ipc-server\n>       | region_leave | r1  | 124.966000 |  0.000460 | fsmonitor    |\n> label:handle_client\n> 15:38:40.079662 ...n/fsmonitor--daemon.c:969 | d1 | th02:ipc-server\n>       | region_enter | r1  | 247.186960 |           | fsmonitor    |\n> label:handle_client\n> 15:38:40.079662 ...n/fsmonitor--daemon.c:970 | d1 | th02:ipc-server\n>       | data         | r1  | 247.187067 |  0.000107 | fsmonitor    |\n> ..request:1658950720017776200\n> 15:38:40.079662 ...n/fsmonitor--daemon.c:786 | d1 | th02:ipc-server\n>       | data         | r1  | 247.187328 |  0.000368 | fsmonitor    |\n> ..response/token:builtin:0.12336.20220727T193432.938608Z:0\n> 15:38:40.079662 ...n/fsmonitor--daemon.c:822 | d1 | th02:ipc-server\n>       | data         | r1  | 247.187448 |  0.000488 | fsmonitor    |\n> ..response/trivial:1\n> 15:38:40.079662 ...n/fsmonitor--daemon.c:974 | d1 | th02:ipc-server\n>       | region_leave | r1  | 247.187491 |  0.000531 | fsmonitor    |\n> label:handle_client\n> 15:42:14.719673 ...n/fsmonitor--daemon.c:969 | d1 | th03:ipc-server\n>       | region_enter | r1  | 461.821373 |           | fsmonitor    |\n> label:handle_client\n> 15:42:14.719673 ...n/fsmonitor--daemon.c:970 | d1 | th03:ipc-server\n>       | data         | r1  | 461.821429 |  0.000056 | fsmonitor    |\n> ..request:1658950934652816400\n> 15:42:14.719673 ...n/fsmonitor--daemon.c:786 | d1 | th03:ipc-server\n>       | data         | r1  | 461.821467 |  0.000094 | fsmonitor    |\n> ..response/token:builtin:0.12336.20220727T193432.938608Z:0\n> 15:42:14.719673 ...n/fsmonitor--daemon.c:822 | d1 | th03:ipc-server\n>       | data         | r1  | 461.821486 |  0.000113 | fsmonitor    |\n> ..response/trivial:1\n> 15:42:14.719673 ...n/fsmonitor--daemon.c:974 | d1 | th03:ipc-server\n>       | region_leave | r1  | 461.821497 |  0.000124 | fsmonitor    |\n> label:handle_client\n>\n> Note that this is a slightly hacked build of mine where I disabled the\n> check for network filesystems. I also added some additional logging\n> that tells me that the query is successful, it's just that the\n> response is trivial. The sandbox I am using is on the network and\n> being accessed from my Windows VM.\n\nSince you already \"hacked\" it, why not instrument it a bit more, e.g.\noffering some trace2 message for all the places where `do_trivial` is set\nto 1 in builtin/fsmonitor--daemon.c?\n\nOr maybe you need to use `GIT_TRACE2_EVENT` instead of `GIT_TRACE2_PERF`\n(I vaguely remember that `error()` messages are only logged in one of\nthese two modes).\n\nCiao,\nJohannes\n"},{"id":"460366","messageId":"CAMxJVdEPd3h3WyXC+MjN9dmKyQOTMb9+Nsp=Vm-bt7J+kL202g@mail.gmail.com","threadId":"58231","inReplyTo":"840r6312-3r19-n087-68s1-rpo1n9869osn@tzk.qr","subject":"Re: fsmonitor: perpetual trivial response","fromName":"Eric D","fromEmail":"eric.decosta@gmail.com","sentAt":"2022-08-01T18:19:24Z","receivedAt":"2022-08-01T18:19:41Z","isPatch":false,"sender":{"key":"eric.decosta@gmail.com","avatar":null},"body":"On Thu, Jul 28, 2022 at 9:48 AM Johannes Schindelin\n<Johannes.Schindelin@gmx.de> wrote:\n>\n> Hi Eric,\n>\n> On Wed, 27 Jul 2022, Eric D wrote:\n>\n> > fsmonitor daemon was started in the background (i.e. git\n> > fsmonitor--daemon start) so I could enable trace2 logging.\n> >\n> > 15:36:37.860862 ...n/fsmonitor--daemon.c:969 | d1 | th01:ipc-server\n> >       | region_enter | r1  | 124.965540 |           | fsmonitor    |\n> > label:handle_client\n> > 15:36:37.860862 ...n/fsmonitor--daemon.c:970 | d1 | th01:ipc-server\n> >       | data         | r1  | 124.965809 |  0.000269 | fsmonitor    |\n> > ..request:1658950597810367000\n> > 15:36:37.860862 ...n/fsmonitor--daemon.c:786 | d1 | th01:ipc-server\n> >       | data         | r1  | 124.965892 |  0.000352 | fsmonitor    |\n> > ..response/token:builtin:0.12336.20220727T193432.938608Z:0\n> > 15:36:37.860862 ...n/fsmonitor--daemon.c:822 | d1 | th01:ipc-server\n> >       | data         | r1  | 124.965969 |  0.000429 | fsmonitor    |\n> > ..response/trivial:1\n> > 15:36:37.860862 ...n/fsmonitor--daemon.c:974 | d1 | th01:ipc-server\n> >       | region_leave | r1  | 124.966000 |  0.000460 | fsmonitor    |\n> > label:handle_client\n> > 15:38:40.079662 ...n/fsmonitor--daemon.c:969 | d1 | th02:ipc-server\n> >       | region_enter | r1  | 247.186960 |           | fsmonitor    |\n> > label:handle_client\n> > 15:38:40.079662 ...n/fsmonitor--daemon.c:970 | d1 | th02:ipc-server\n> >       | data         | r1  | 247.187067 |  0.000107 | fsmonitor    |\n> > ..request:1658950720017776200\n> > 15:38:40.079662 ...n/fsmonitor--daemon.c:786 | d1 | th02:ipc-server\n> >       | data         | r1  | 247.187328 |  0.000368 | fsmonitor    |\n> > ..response/token:builtin:0.12336.20220727T193432.938608Z:0\n> > 15:38:40.079662 ...n/fsmonitor--daemon.c:822 | d1 | th02:ipc-server\n> >       | data         | r1  | 247.187448 |  0.000488 | fsmonitor    |\n> > ..response/trivial:1\n> > 15:38:40.079662 ...n/fsmonitor--daemon.c:974 | d1 | th02:ipc-server\n> >       | region_leave | r1  | 247.187491 |  0.000531 | fsmonitor    |\n> > label:handle_client\n> > 15:42:14.719673 ...n/fsmonitor--daemon.c:969 | d1 | th03:ipc-server\n> >       | region_enter | r1  | 461.821373 |           | fsmonitor    |\n> > label:handle_client\n> > 15:42:14.719673 ...n/fsmonitor--daemon.c:970 | d1 | th03:ipc-server\n> >       | data         | r1  | 461.821429 |  0.000056 | fsmonitor    |\n> > ..request:1658950934652816400\n> > 15:42:14.719673 ...n/fsmonitor--daemon.c:786 | d1 | th03:ipc-server\n> >       | data         | r1  | 461.821467 |  0.000094 | fsmonitor    |\n> > ..response/token:builtin:0.12336.20220727T193432.938608Z:0\n> > 15:42:14.719673 ...n/fsmonitor--daemon.c:822 | d1 | th03:ipc-server\n> >       | data         | r1  | 461.821486 |  0.000113 | fsmonitor    |\n> > ..response/trivial:1\n> > 15:42:14.719673 ...n/fsmonitor--daemon.c:974 | d1 | th03:ipc-server\n> >       | region_leave | r1  | 461.821497 |  0.000124 | fsmonitor    |\n> > label:handle_client\n> >\n> > Note that this is a slightly hacked build of mine where I disabled the\n> > check for network filesystems. I also added some additional logging\n> > that tells me that the query is successful, it's just that the\n> > response is trivial. The sandbox I am using is on the network and\n> > being accessed from my Windows VM.\n>\n> Since you already \"hacked\" it, why not instrument it a bit more, e.g.\n> offering some trace2 message for all the places where `do_trivial` is set\n> to 1 in builtin/fsmonitor--daemon.c?\n>\n> Or maybe you need to use `GIT_TRACE2_EVENT` instead of `GIT_TRACE2_PERF`\n> (I vaguely remember that `error()` messages are only logged in one of\n> these two modes).\n>\n> Ciao,\n> Johannes\n\nMy sandbox is sparse, but it is not \"cone compliant\"; temporarily\ndisabling sparse checkout seems to have (temporarily) resolved this\nissue - at least for my purposes of testing fsmonitor out on network\nfilesystems.\n\n-Eric\n"},{"id":"460430","messageId":"5fb7ff38-dfa1-909a-1448-dfb779e1b5fd@jeffhostetler.com","threadId":"58231","inReplyTo":"CAMxJVdEPd3h3WyXC+MjN9dmKyQOTMb9+Nsp=Vm-bt7J+kL202g@mail.gmail.com","subject":"Re: fsmonitor: perpetual trivial response","fromName":"Jeff Hostetler","fromEmail":"git@jeffhostetler.com","sentAt":"2022-08-02T13:51:01Z","receivedAt":"2022-08-02T13:54:36Z","isPatch":false,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"\n\nOn 8/1/22 2:19 PM, Eric D wrote:\n> On Thu, Jul 28, 2022 at 9:48 AM Johannes Schindelin\n> <Johannes.Schindelin@gmx.de> wrote:\n>>\n>> Hi Eric,\n>>\n>> On Wed, 27 Jul 2022, Eric D wrote:\n>>\n>>> fsmonitor daemon was started in the background (i.e. git\n>>> fsmonitor--daemon start) so I could enable trace2 logging.\n>>>\n>>> 15:36:37.860862 ...n/fsmonitor--daemon.c:969 | d1 | th01:ipc-server\n>>>        | region_enter | r1  | 124.965540 |           | fsmonitor    |\n>>> label:handle_client\n>>> 15:36:37.860862 ...n/fsmonitor--daemon.c:970 | d1 | th01:ipc-server\n>>>        | data         | r1  | 124.965809 |  0.000269 | fsmonitor    |\n>>> ..request:1658950597810367000\n>>> 15:36:37.860862 ...n/fsmonitor--daemon.c:786 | d1 | th01:ipc-server\n>>>        | data         | r1  | 124.965892 |  0.000352 | fsmonitor    |\n>>> ..response/token:builtin:0.12336.20220727T193432.938608Z:0\n>>> 15:36:37.860862 ...n/fsmonitor--daemon.c:822 | d1 | th01:ipc-server\n>>>        | data         | r1  | 124.965969 |  0.000429 | fsmonitor    |\n>>> ..response/trivial:1\n>>> 15:36:37.860862 ...n/fsmonitor--daemon.c:974 | d1 | th01:ipc-server\n>>>        | region_leave | r1  | 124.966000 |  0.000460 | fsmonitor    |\n>>> label:handle_client\n>>> 15:38:40.079662 ...n/fsmonitor--daemon.c:969 | d1 | th02:ipc-server\n>>>        | region_enter | r1  | 247.186960 |           | fsmonitor    |\n>>> label:handle_client\n>>> 15:38:40.079662 ...n/fsmonitor--daemon.c:970 | d1 | th02:ipc-server\n>>>        | data         | r1  | 247.187067 |  0.000107 | fsmonitor    |\n>>> ..request:1658950720017776200\n>>> 15:38:40.079662 ...n/fsmonitor--daemon.c:786 | d1 | th02:ipc-server\n>>>        | data         | r1  | 247.187328 |  0.000368 | fsmonitor    |\n>>> ..response/token:builtin:0.12336.20220727T193432.938608Z:0\n>>> 15:38:40.079662 ...n/fsmonitor--daemon.c:822 | d1 | th02:ipc-server\n>>>        | data         | r1  | 247.187448 |  0.000488 | fsmonitor    |\n>>> ..response/trivial:1\n>>> 15:38:40.079662 ...n/fsmonitor--daemon.c:974 | d1 | th02:ipc-server\n>>>        | region_leave | r1  | 247.187491 |  0.000531 | fsmonitor    |\n>>> label:handle_client\n>>> 15:42:14.719673 ...n/fsmonitor--daemon.c:969 | d1 | th03:ipc-server\n>>>        | region_enter | r1  | 461.821373 |           | fsmonitor    |\n>>> label:handle_client\n>>> 15:42:14.719673 ...n/fsmonitor--daemon.c:970 | d1 | th03:ipc-server\n>>>        | data         | r1  | 461.821429 |  0.000056 | fsmonitor    |\n>>> ..request:1658950934652816400\n>>> 15:42:14.719673 ...n/fsmonitor--daemon.c:786 | d1 | th03:ipc-server\n>>>        | data         | r1  | 461.821467 |  0.000094 | fsmonitor    |\n>>> ..response/token:builtin:0.12336.20220727T193432.938608Z:0\n>>> 15:42:14.719673 ...n/fsmonitor--daemon.c:822 | d1 | th03:ipc-server\n>>>        | data         | r1  | 461.821486 |  0.000113 | fsmonitor    |\n>>> ..response/trivial:1\n>>> 15:42:14.719673 ...n/fsmonitor--daemon.c:974 | d1 | th03:ipc-server\n>>>        | region_leave | r1  | 461.821497 |  0.000124 | fsmonitor    |\n>>> label:handle_client\n>>>\n>>> Note that this is a slightly hacked build of mine where I disabled the\n>>> check for network filesystems. I also added some additional logging\n>>> that tells me that the query is successful, it's just that the\n>>> response is trivial. The sandbox I am using is on the network and\n>>> being accessed from my Windows VM.\n>>\n>> Since you already \"hacked\" it, why not instrument it a bit more, e.g.\n>> offering some trace2 message for all the places where `do_trivial` is set\n>> to 1 in builtin/fsmonitor--daemon.c?\n>>\n>> Or maybe you need to use `GIT_TRACE2_EVENT` instead of `GIT_TRACE2_PERF`\n>> (I vaguely remember that `error()` messages are only logged in one of\n>> these two modes).\n>>\n>> Ciao,\n>> Johannes\n> \n> My sandbox is sparse, but it is not \"cone compliant\"; temporarily\n> disabling sparse checkout seems to have (temporarily) resolved this\n> issue - at least for my purposes of testing fsmonitor out on network\n> filesystems.\n> \n> -Eric\n> \n\nThe first time status runs and it starts the daemon, you'll get\na trivial response (because the daemon doesn't have a sync point\nestablished with client commands yet).\n\nSubsequent client commands (like status) will continue to receive\na trivial response *UNTIL* one of them updates the index and records\nthe sync point (token) into the index.  That is, until the index\nis updated with a valid token, they will continue to send not-sync'd\ntimestamp in the request header and get a trivial response.\n\n > ..request:1658950934652816400\n >\n > ..response/token:builtin:0.12336.20220727T193432.938608Z:0\n > ..response/trivial:1\n\nWhen/if any of these client commands update the the index, they will\nwrite the response token to the FSM index extension, and subsequent\nrequests will send it to the daemon.  The daemon will then start sending\nnon-trivial responses (possibly with an updated token).\n\n > ..request:builtin:0.12336.20220727T193432.938608Z:0\n >\n > ..response/token:builtin:0.12336.20220727T193432.938608Z:1\n\n\nCommands like `git status` may be read-only or may update the `lstat`\ntimes in cache-entries and rewrite the index.  It is not always clear\nwhen a status command will and will not rewrite the index -- it just\ndepends on what kind of changes it sees and how many.  My point is\nthat it will not update the token unless it updates the index, so you\nneed to watch for that on the client side rather than looking at the\ndaemon log.\n\nHope this helps,\nJeff\n"}]}