71

Does Safari in same circumstances behave the same?

    Magebarf

    And a second follow up; Left the Mac Mini sleeping since morning, and actually had the Activity Monitor in the same place, meaning the Cmd+Shift+5 section was already pre-selected, and now I managed to catch the process list a little earlier, with more margin before the CPU pressure was lowered:

    Now you can definitely see the reason why I'm assuming the Orion activity is what is hiding behind the kernel_task usage... 🙂

        Vlad I will try to see what I can do to compare with Safari's behavior.
        Haven't really been running Safari much since I've started using Orion, so my attempts will probably be "synthetic" at best.

        (As a side note, more as a curiosity, I can add that I had similar wake-up behavior on my previous Mac Mini 2012, so x86_64, running Firefox, which had a long running bug spanning plenty of releases: https://bugzilla.mozilla.org/show_bug.cgi?id=1415923 )

            rosenrot on your end, is the behavior noticeable even prior to logging in/unlocking?
            On my end the password unlock screen is extremely sluggish when this happens, giving a hint about what's to come.

                Magebarf Exactly how you describe it. The login screen is already extremely laggy beforehand. This is how I identified the issue originally. I didn’t see this laggy behaviour on my brand new macbook before. It took me a while to identify Orion as its source.

                In general the login takes not even a second but having Orion open makes it lasting 5-10 seconds on my end.

                    In general for a good bug report we need these two things

                    • Establish it is an Orion bug and not macOS/WebKit bug. In this case comparing Orion behavior with Safari behavior in same circumstances (no extensions loaded, similar websites loaded) is best we can do to establish this.

                    • List exact steps to reproduce the problem (froma. new clean Orion install/profile)

                    When we have both we can look deeper into the problem.

                      Vlad

                      Right there with you, and slowly progressing to gather these! (I'm a developer as well, so know how annoying it can be when the right info and insights are not available.)

                      To preface this report, I have to say that the tricky part here is "how long is enough", as the CPU load seems to be tied to how long time the Mac has been allowed to sleep. This is also what's going to make a reproduction instruction tricky. So, for easy verification I left the Mac over night, giving it close to 10 hours.

                      As per request, I "replicated" my Orion setup by opening each and every page I had in Safari (BTW, is there any built-in function to gather all of the URLs open in various tabs, or maybe even a tool to quickly open up all open pages in Safari? This could speed up quite a bit).

                      As for Extensions, I disabled them all and then restarted Safari. Is this enough, that the extensions are still installed but disabled from loading? Also, same question goes for Orion, as I guess this will one of the next tests.

                      The part where this test becomes a bit more "synthetic" is that for each of the 45 tabs opened I simply entered the URL and loaded the page. I did not fully log in to the individual pages and services.

                      Then, I shut down Orion, and left the Mac with Safari open over night.
                      When I logged in a few minutes ago, I went straight in, no sluggishness on the lock screen, and no noticeable slow down in MacOS in general.
                      Screenshot attached shows a minimal peak just after logging in.

                      So, as for way forward, I see two options as for what to do over night:

                      1. Refine the "synthetic" Safari test, by logging in to the pages, making any background activities tied to accounts behave closer to Orion.
                      2. Disable the extensions in Orion and see if that has any effect.
                        As per the question above, is it enough just to disable them from loading from the Extension management dialog, or do they even need to be uninstalled?

                      As for reproduction, I will revisit this after the two above has been tested. Maybe @rosenrot has done some additional attempts for reproduction since the initial post?

                        4 days later

                        I've been running Orion now for a few days with all my extensions disabled, and I'm still seeing the same results.

                        This issue does not seem to be extension related.

                        Next, will try to "improve" correctness of Safari test and run over night.

                        Additionally, I'm just about to pick up a new MacBook which will aid me in testing out a blank slate, to try to reproduce the error from a fresh installation.

                        Sounds good, thanks for 'owning' this bug.

                          Vlad

                          This morning I had an occurence where the behavior was not consistent. For some reason even with Orion still active over night, no sluggishness during or after the login.

                          What I'm thinking/wondering is if this may be related to the state of specific tabs, which are loaded/active etc.?
                          Sorry if it is a stupid question, but is there any "tab index" or similar page where one can see an inventory of open tabs and with the current state of the tab? I'm thinking this could be tied to a specific web page behavior and such a tab state inventory would over a number of tests allow to find the most likely candidate to be causing the issues...

                          Edit: Found the reference to ~/Library/Application\ Support/Orion/Defaults/browser_state.plist in the Orion FAQ/Technical Information, but seeing as that file is only 40 bytes, I really don't think that it's keeping the current state of tabs...
                          The named_windows.plistdoes look a bit more promising though.

                          Edit2: Upon every log in, I will try to perform the following to build a record of tab states over time:

                          cp ~/Library/Application\ Support/Orion/Defaults/named_windows.plist ~/Documents/bugreports/orion-tabstate/named_windows-`date +%Y-%m-%d-%H%M%S`.plist

                          Edit3: Refining above even further, as I also realized it would be good with some type of metadata about how long the computer has been sleeping at the point the plist was copied as well.
                          So, full command line as follows:

                          mkdir ~/Documents/bugreports/orion-tabstate/`date +%Y-%m-%d-%H%M%S` && cd "$_" ; cp ~/Library/Application\ Support/Orion/Defaults/named_windows.plist ./ ; pmset -g log | grep -e " Sleep " -e " Wake " | tail -100 > pmset.log

                          (Not properly formatted above; After "Sleep" and "Wake" there is actually double space characters to improve the filtering)
                          And to break it down:

                          • mkdir ... && cd "$_" creates a new folder with date and time as name, and immediately changes directory to the last argument of the mkdir command (making the newly created folder the working directory).
                          • cp simply copies the named_windows.plist into the the working directory.
                          • pmset -g log retrieves the power management settings log greping it for sleep and wake events and saving the tail (last) 100 log rows output into pmset.log in the working directory.
                            • 100 is an arbitrary number which may or may not have to be tweaked later on...
                          • Vlad replied to this.

                              Magebarf Cool, and feel free to update/add to Orion technical docs. Some nice hacks here.

                                  I've been tracking this over a number of unlocks, and while I've yet started looking into manipulating the plists to compare the "relevant" parts of it, there is a seemingly close correlation between the total size of the named_windows.plist file with the sluggishness of the system after unlock.

                                  Additionally, qutting Orion and starting it back up seems to "reset" the size of the file.

                                  Prior to restart of Orion the file on my system was around 450kB and had about a minute long window of slowdown.
                                  Quitting Orion and starting it again, and the file size went down to 75kB.
                                  What seems to cause the difference in file sizes are mainly the sessionStateData properties, which are almost missing entirely in the lower size after a fresh restart.

                                  13 days later

                                  Still haven't found time to figure out how to properly process and analyze the contents of the files (I'm kind of guessing conversion to json and then using jq will be easiest, as I've found no good tools to work directly with the plists), and what parameters may have effect.
                                  Edit: See next post.

                                  I have managed to rule out one of the variables, and that is the time the computer sleeps. Just letting it go to sleep and comining back 15 minutes later is roughly as bad as if it has been asleep for a full day.

                                  However, this variable goes a bit hand in hand with another one that has become more apparent; The uptime of the Orion process itself. Having the worst of these slowdowns, and then restarting Orion, the next few times you wake your computer from sleep it will be unaffected. After a day or two, it starts getting back to the sluggish state again at the unlock.

                                  Still tracking, will see if I can find any factual evidence of this in the files I'm snapshotting for each event.

                                    A relevant finding, with two implications:
                                    The main growing part of the named_windows.plist files is the sessionStateData in each of the tabStates entries which I so far only saw as custom binary data embedded.
                                    The relevant finding is that this is in itself binary plist data, recursively embedded as a binary object in the named_windows.plist file.

                                    The first implication, which is actually what led me to figure this out, is that PlistBuddy(not available in path, but at /usr/libexec/PlistBuddy in more recent MacOS versions) decodes this recursively. So, if you want to view the contents, use PlustBuddy like this:
                                    % /usr/libexec/PlistBuddy -c "print :Array:tabStates:0:sessionStateData" /path/to/named_windows.plist, where the :0is the array index for the specific tabState object you want to watch.

                                    The second implication, not so much because it's a embedded binary plist but more because binary data exists: plutil do not want to convert the plist file to json due to not being able to encode the binary data in a suitable format for json.
                                    The easy workaround I've found for this is a small python utility doing the conversion and encoding the binary to escaped strings: https://github.com/varenc/plist2json
                                    Of course requires python3, but at least MacOS prompts you to install that automatically if you try to execute the script.

                                      And, unless the interesting parts are in the actual sessionStateData, and it will be fine to only see the length and a few bytes of the contents, an even easier approach to convert the file to a diffable file:
                                      plutil -p named_windows.plist > named_windows_decoded.txt

                                        Magebarf Thanks for your debugging work, we have this planned for 125.

                                            12 days later

                                            I can also say that the issue is almost gone on my computer already with 0.99.124 (may have to do with me not "waking up" all the tabs after every Orion restart as I have many dormant ones).

                                            CPU still does spike for a few seconds after login, and the unlock screen can still be sluggish, but it's gone so much quicker than it was before. And, at thia point in time, I cannot say for sure that the CPU spike can be attributed to Orion either.

                                            Worth mentioning is that I have had a little more frequent reboots, due to driver updates etc. which means the uptime for the Orion process has not really been up on the same levels as before. I will see if I reach a week or two of uptime again and see if the issue reoccurs.

                                              4 months later
                                              ForumNinja404 changed the title to V123 High CPU usage after wakeup .
                                                a month later
                                                8 months later
                                                Merged 28 posts from V123 High CPU usage after wakeup.