aw-android icon indicating copy to clipboard operation
aw-android copied to clipboard

Published 20 hours ago • verified publisher icon ActivityWatch

Events not stored correctly (and therefore not reported correctly either)

Open nicolae-stroncea opened this issue 4 years ago • 9 comments

I realized why there are a lot of duration:0 events in the raw data store. I initially thought this was due to storing the same events twice(https://github.com/ActivityWatch/aw-android/pull/38), however this turned out not to be the case.

Android's default UsageStatsManager should actually produce close to no events of duration 0 for apps with a UI. Every UI app has a move_to_foreground and a move_to_background, so all events should have at least some milliseconds of time on screen if captured correctly.

Here's what's happening:

Android has 2 other events: screen_interactive and screen_non_interactive. Whenever you're in an application, and the screen goes to sleep, or you lock the screen, the screen_non_interactive event shoots first, only then followed by a move_to_background event. Because AW merges events next to each other, this essentially adds an event in the middle, and breaks the chain. Let's say you start Firefox. You get a move_to_foreground when you start Firefox, you spend 20 minutes, and then lock the screen. Android sends a screen_non_interactive, then a move_to_background. As a result both Firefox events have duration 0 instead of 20 minutes.

Here's an example:

                {
                    "id": 60381,
                    "timestamp": "2020-06-14T00:00:45.523Z",
                    "duration": 0.0,
                    "data": {
                        "app": "Firefox",
                        "classname": "org.mozilla.gecko.BrowserApp",
                        "package": "org.mozilla.firefox"
                    }
                },
                {
                    "id": 60380,
                    "timestamp": "2020-06-14T00:00:45.435Z",
                    "duration": 0.0,
                    "data": {
                        "app": "Android system",
                        "package": "android"
                    }
                },
                {
                    "id": 60379,
                    "timestamp": "2020-06-13T23:57:20.015Z",
                    "duration": 0.0,
                    "data": {
                        "app": "Firefox",
                        "classname": "org.mozilla.gecko.BrowserApp",
                        "package": "org.mozilla.firefox"
                    }
                },

Look at the timestamps of Firefox and Android System for confirmation: 2020-06-14T00:00:45.523Z and 2020-06-14T00:00:45.435Z, to see that Android sends them in the order I specified above. Here AW reports I spent 0 time on Firefox, when in reality I spent 3 minutes

This occurs almost every time you lock your phone/your phone goes to sleep by itself, and is probably the main cause for: ActivityWatch/activitywatch/issues/440.

To reproduce

  1. Get the Raw data for the Android Bucket
  2. Take a look at all of the events with duration: 0. Notice how they're separated by the Android System call.

You can also confirm this order by printing out the events to LogCat as they come, making sure to print the event_type with them.

To fix

In SendHeartbeatsTask, when iterating through the loop of events, if the event type is screen_non_interactive, check if next event has same app name as previous event. If they do, then process next event first, and only after that, process screen_non_interactive. Everything else should be the same

To make debugging easier, it would be good to store 'event_type' directly in data. This would make it a lot easier to later look through the events and make sure the behaviours between all event types are correct.

EDIT: Also related to this: #34

nicolae-stroncea avatar Jun 14 '20 15:06 nicolae-stroncea

Very nicely investigated!

One question I have is do we really need to consider the SCREEN_NON_INTERACTIVE events at all? It would significantly complicate the logic to have to reorder the events as you suggest.

Here I've printed the event types in order:

2020-06-22 16:44:09.273 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 1
2020-06-22 16:44:09.370 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 16
2020-06-22 16:44:09.380 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 2
2020-06-22 16:44:09.381 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 15
2020-06-22 16:44:09.382 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 1
2020-06-22 16:44:09.388 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 1
2020-06-22 16:44:09.389 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 2
2020-06-22 16:44:09.411 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 1
2020-06-22 16:44:09.415 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 2
2020-06-22 16:44:09.431 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 1
2020-06-22 16:44:09.432 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 2
2020-06-22 16:44:09.455 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 1
2020-06-22 16:44:09.456 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 1
2020-06-22 16:44:09.457 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 2
2020-06-22 16:44:09.457 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 16
2020-06-22 16:44:09.458 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 2
2020-06-22 16:44:09.459 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 15
2020-06-22 16:44:09.459 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 1
2020-06-22 16:44:09.474 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 1
2020-06-22 16:44:09.475 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 2
2020-06-22 16:44:09.476 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 1
2020-06-22 16:44:09.477 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 2
2020-06-22 16:44:09.477 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 2
2020-06-22 16:44:09.478 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 1
2020-06-22 16:44:09.479 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 2
2020-06-22 16:44:09.495 6498-6559/net.activitywatch.android.debug D/UsageStatsWatcher: Event type: 1

From this small sample, it seems that 2 (ACTIVITY_PAUSED) always follows 16 (SCREEN_NON_INTERACTIVE) and that 1 (ACTIVITY_RESUMED) always follows 15 (SCREEN_INTERACTIVE).

I also noticed that sometimes there are events with type 1 or 2 in succession, which was unexpected to me.

Lets do some further investigation, but include timestamps:

2020-06-22 16:48:17.631 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:35:54.887Z
2020-06-22 16:48:17.740 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 16 at 2020-06-22T14:36:10.214Z
2020-06-22 16:48:17.755 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:36:10.574Z
2020-06-22 16:48:17.765 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 15 at 2020-06-22T14:43:23.177Z
2020-06-22 16:48:17.766 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:43:23.738Z
2020-06-22 16:48:17.774 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:43:31.276Z
2020-06-22 16:48:17.776 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:43:33.462Z
2020-06-22 16:48:17.802 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:43:33.481Z
2020-06-22 16:48:17.806 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:43:33.552Z
2020-06-22 16:48:17.826 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:43:33.573Z
2020-06-22 16:48:17.828 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:43:38.893Z
2020-06-22 16:48:17.845 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:43:39.105Z
2020-06-22 16:48:17.847 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:43:44.869Z
2020-06-22 16:48:17.849 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:43:44.896Z
2020-06-22 16:48:17.850 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 16 at 2020-06-22T14:43:45.376Z
2020-06-22 16:48:17.851 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:43:45.741Z
2020-06-22 16:48:17.852 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 15 at 2020-06-22T14:43:48.916Z
2020-06-22 16:48:17.853 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:43:49.772Z
2020-06-22 16:48:17.924 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:43:50.939Z
2020-06-22 16:48:17.925 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:43:50.945Z
2020-06-22 16:48:17.928 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:43:56.669Z
2020-06-22 16:48:17.929 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:43:56.677Z
2020-06-22 16:48:17.931 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:44:04.901Z
2020-06-22 16:48:17.932 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:44:04.901Z
2020-06-22 16:48:17.934 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:44:04.965Z
2020-06-22 16:48:17.961 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:44:04.989Z
2020-06-22 16:48:17.963 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:44:08.142Z
2020-06-22 16:48:17.977 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:44:08.422Z
2020-06-22 16:48:17.979 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:48:11.323Z
2020-06-22 16:48:17.979 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:48:13.271Z
2020-06-22 16:48:17.994 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:48:13.286Z
2020-06-22 16:48:17.995 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:48:13.379Z
2020-06-22 16:48:18.010 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:48:13.398Z
2020-06-22 16:48:18.011 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:48:16.443Z
2020-06-22 16:48:18.025 7188-7342/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:48:16.705Z
2020-06-22 16:49:00.489 7188-7538/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:48:16.705Z
2020-06-22 16:49:00.510 7188-7538/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:48:54.151Z
2020-06-22 16:49:00.512 7188-7538/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:48:54.163Z
2020-06-22 16:49:00.518 7188-7538/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:48:58.156Z
2020-06-22 16:49:00.520 7188-7538/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:48:58.159Z
2020-06-22 16:49:00.520 7188-7538/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:48:59.090Z
2020-06-22 16:49:00.535 7188-7538/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:48:59.109Z
2020-06-22 16:49:00.536 7188-7538/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:48:59.647Z
2020-06-22 16:49:00.550 7188-7538/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:48:59.655Z
2020-06-22 16:49:00.551 7188-7538/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:49:00.405Z
2020-06-22 16:49:00.552 7188-7538/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:49:00.411Z
2020-06-22 16:49:15.508 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:49:00.411Z
2020-06-22 16:49:15.843 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 16 at 2020-06-22T14:49:15.001Z
2020-06-22 16:49:15.845 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 15 at 2020-06-22T14:49:15.357Z
2020-06-22 16:49:15.892 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:49:15.426Z
2020-06-22 16:49:15.895 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:49:15.436Z
2020-06-22 16:49:15.932 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:49:15.467Z
2020-06-22 16:49:16.212 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:49:15.426Z
2020-06-22 16:49:16.231 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:49:15.436Z
2020-06-22 16:49:16.247 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:49:15.467Z
2020-06-22 16:49:16.263 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:49:16.153Z
2020-06-22 16:49:18.733 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:49:15.426Z
2020-06-22 16:49:18.747 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:49:15.436Z
2020-06-22 16:49:18.761 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:49:15.467Z
2020-06-22 16:49:18.775 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:49:16.153Z
2020-06-22 16:49:18.790 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:49:17.176Z
2020-06-22 16:49:18.791 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:49:17.180Z
2020-06-22 16:49:18.792 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:49:18.008Z
2020-06-22 16:49:18.793 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:49:18.014Z
2020-06-22 16:49:18.794 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:49:18.661Z
2020-06-22 16:49:18.795 7188-7553/net.activitywatch.android.debug D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:49:18.663Z

Here we have one case of a 16 being triggered without an immediately following 2, possibly due to a quick lock/unlock.

ErikBjare avatar Jun 22 '20 14:06 ErikBjare

Here are some logs with more info:

16:59:03.829 D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:49:18.663Z with data {"app":"ActivityWatch","package":"net.activitywatch.android.debug","classname":"net.activitywatch.android.MainActivity"}
16:59:03.930 D/UsageStatsWatcher: Event type 16 at 2020-06-22T14:54:05.336Z with data {"app":"Android System","package":"android"}
16:59:03.932 D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:54:05.773Z with data {"app":"ActivityWatch","package":"net.activitywatch.android.debug","classname":"net.activitywatch.android.MainActivity"}
16:59:03.933 D/UsageStatsWatcher: Event type 15 at 2020-06-22T14:58:56.541Z with data {"app":"Android System","package":"android"}
16:59:03.935 D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:58:57.019Z with data {"app":"ActivityWatch","package":"net.activitywatch.android.debug","classname":"net.activitywatch.android.MainActivity"}
16:59:04.005 D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:58:57.560Z with data {"app":"Nova Launcher","package":"com.teslacoilsw.launcher","classname":"com.teslacoilsw.launcher.NovaLauncher"}
16:59:04.007 D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:58:58.630Z with data {"app":"Nova Launcher","package":"com.teslacoilsw.launcher","classname":"com.teslacoilsw.launcher.NovaLauncher"}
16:59:04.026 D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:58:58.638Z with data {"app":"Security","package":"com.miui.securitycenter","classname":"com.miui.permcenter.install.AdbInstallActivity"}
16:59:04.028 D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:58:58.704Z with data {"app":"Security","package":"com.miui.securitycenter","classname":"com.miui.permcenter.install.AdbInstallActivity"}
16:59:04.043 D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:58:58.723Z with data {"app":"Nova Launcher","package":"com.teslacoilsw.launcher","classname":"com.teslacoilsw.launcher.NovaLauncher"}
16:59:25.941 D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:58:58.723Z with data {"app":"Nova Launcher","package":"com.teslacoilsw.launcher","classname":"com.teslacoilsw.launcher.NovaLauncher"}
16:59:25.968 D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:59:02.432Z with data {"app":"Nova Launcher","package":"com.teslacoilsw.launcher","classname":"com.teslacoilsw.launcher.NovaLauncher"}
16:59:25.997 D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:59:02.697Z with data {"app":"ActivityWatch","package":"net.activitywatch.android.debug","classname":"net.activitywatch.android.MainActivity"}
16:59:25.998 D/UsageStatsWatcher: Event type 16 at 2020-06-22T14:59:20.403Z with data {"app":"Android System","package":"android"}
16:59:26.000 D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:59:20.806Z with data {"app":"ActivityWatch","package":"net.activitywatch.android.debug","classname":"net.activitywatch.android.MainActivity"}
16:59:26.009 D/UsageStatsWatcher: Event type 15 at 2020-06-22T14:59:21.069Z with data {"app":"Android System","package":"android"}
16:59:26.017 D/UsageStatsWatcher: Event type 16 at 2020-06-22T14:59:22.010Z with data {"app":"Android System","package":"android"}
16:59:26.051 D/UsageStatsWatcher: Event type 15 at 2020-06-22T14:59:22.706Z with data {"app":"Android System","package":"android"}
16:59:26.067 D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:59:25.807Z with data {"app":"ActivityWatch","package":"net.activitywatch.android.debug","classname":"net.activitywatch.android.MainActivity"}
16:59:32.291 D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:59:25.807Z with data {"app":"ActivityWatch","package":"net.activitywatch.android.debug","classname":"net.activitywatch.android.MainActivity"}
16:59:32.316 D/UsageStatsWatcher: Event type 16 at 2020-06-22T14:59:29.781Z with data {"app":"Android System","package":"android"}
16:59:32.320 D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:59:30.191Z with data {"app":"ActivityWatch","package":"net.activitywatch.android.debug","classname":"net.activitywatch.android.MainActivity"}
16:59:32.331 D/UsageStatsWatcher: Event type 15 at 2020-06-22T14:59:31.314Z with data {"app":"Android System","package":"android"}
16:59:32.335 D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:59:32.212Z with data {"app":"ActivityWatch","package":"net.activitywatch.android.debug","classname":"net.activitywatch.android.MainActivity"}
16:59:57.417 D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:59:32.212Z with data {"app":"ActivityWatch","package":"net.activitywatch.android.debug","classname":"net.activitywatch.android.MainActivity"}
16:59:57.433 D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:59:44.050Z with data {"app":"Nova Launcher","package":"com.teslacoilsw.launcher","classname":"com.teslacoilsw.launcher.NovaLauncher"}
16:59:57.435 D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:59:44.053Z with data {"app":"ActivityWatch","package":"net.activitywatch.android.debug","classname":"net.activitywatch.android.MainActivity"}
16:59:57.436 D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:59:46.939Z with data {"app":"Nova Launcher","package":"com.teslacoilsw.launcher","classname":"com.teslacoilsw.launcher.NovaLauncher"}
16:59:57.452 D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:59:46.953Z with data {"app":"Gmail","package":"com.google.android.gm","classname":"com.google.android.gm.ui.MailActivityGmail"}
16:59:57.460 D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:59:56.618Z with data {"app":"System UI","package":"com.android.systemui","classname":"com.android.systemui.recents.RecentsActivity"}
16:59:57.462 D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:59:56.680Z with data {"app":"Gmail","package":"com.google.android.gm","classname":"com.google.android.gm.ui.MailActivityGmail"}
16:59:57.463 D/UsageStatsWatcher: Event type 2 at 2020-06-22T14:59:57.324Z with data {"app":"System UI","package":"com.android.systemui","classname":"com.android.systemui.recents.RecentsActivity"}
16:59:57.464 D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:59:57.332Z with data {"app":"ActivityWatch","package":"net.activitywatch.android.debug","classname":"net.activitywatch.android.MainActivity"}
17:00:24.813 D/UsageStatsWatcher: Event type 1 at 2020-06-22T14:59:57.332Z with data {"app":"ActivityWatch","package":"net.activitywatch.android.debug","classname":"net.activitywatch.android.MainActivity"}
17:00:24.828 D/UsageStatsWatcher: Event type 16 at 2020-06-22T15:00:22.054Z with data {"app":"Android System","package":"android"}
17:00:24.829 D/UsageStatsWatcher: Event type 2 at 2020-06-22T15:00:22.463Z with data {"app":"ActivityWatch","package":"net.activitywatch.android.debug","classname":"net.activitywatch.android.MainActivity"}
17:00:24.830 D/UsageStatsWatcher: Event type 15 at 2020-06-22T15:00:24.059Z with data {"app":"Android System","package":"android"}
17:00:24.831 D/UsageStatsWatcher: Event type 1 at 2020-06-22T15:00:24.464Z with data {"app":"ActivityWatch","package":"net.activitywatch.android.debug","classname":"net.activitywatch.android.MainActivity"}

It seems to me like we can drop the 15 and 16 events. But it looks like that won't solve the issue entirely as there can still be consecutive 1 and 2 events, maybe that's non-problematic though.

ErikBjare avatar Jun 22 '20 15:06 ErikBjare

To make debugging easier, it would be good to store 'event_type' directly in data. This would make it a lot easier to later look through the events and make sure the behaviours between all event types are correct.

Storing the varying event_type would break the heartbeat logic completely (almost all events would become 0-duration), so that's not really possible.

ErikBjare avatar Jun 22 '20 15:06 ErikBjare

@ErikBjare seems like in my excitement I missed the obvious choice :))

I think ignoring MOVE_TO_BACKGROUND and MOVE_TO_FOREGROUND makes sense. They're not needed for AFK purposes either since we only report non-afk events in the currentWindow bucket.

Regarding event_type, checked the source code and that makes sense given that merging checks for events to be equal everywhere but the timestamp.

Regarding your logs:

They're really surprising to me, because we get events in very different orders (I'm on Android 9, on a OnePlus 3). In my logs, consecutive events are almost always in the form 1-2, which makes a lot of sense to me, since you will stop an existing activity(event 2) before you start a new one(event 1). If I launch ActivityWatch, then launch Chrome. I'll get ActivityWatch event type 1 ActivityWatch event type 2 Chrome event type 1 Chrome event type 2 This works optimally for AW as that allows events to be merged together to accurately depict the time.

Your events seem to be in an order which will actually avoid merging, and report both ActivityWatch and Chrome with time 0

nicolae-stroncea avatar Jun 22 '20 15:06 nicolae-stroncea

A couple of other follow-up notes:

With the PR applied, AW reports durations with exact or very similar accuracy to SmarterTime and ActionDash, so it seems like ignoring MOVE_TO_BACKGROUND and MOVE_TO_FOREGROUND will result in the same benefits, and fix the issue.

There are a couple of instances when the time still varies (now by a lot less) by at most a couple of minutes in my tests, where AW underestimates some durations compared to other apps

nicolae-stroncea avatar Jun 22 '20 16:06 nicolae-stroncea

Fixed in #40, some small discrepancies might still exist but should be good enough for now.

ErikBjare avatar Jun 30 '20 10:06 ErikBjare

It seems like I still have some significant discrepancies, so we probably need to to do something about the consecutive 1 and 2 events.

ErikBjare avatar Aug 17 '20 15:08 ErikBjare

@ErikBjare do the discrepancies you experience occur consistently, or have you noticed that around some specific actions? I haven't noticed anything wrong on my reports. Wondering if this is a difference due to different Android versions

On Mon, Aug 17, 2020 at 08:17, Erik Bjäreholt [email protected] wrote:

Reopened #39 https://github.com/ActivityWatch/aw-android/issues/39.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/ActivityWatch/aw-android/issues/39#event-3662363475, or unsubscribe https://github.com/notifications/unsubscribe-auth/AJMED6AFHM5PH5FVLW2THQDSBFCZPANCNFSM4N5P2ERA.

nicolae-stroncea avatar Aug 22 '20 03:08 nicolae-stroncea

@nicolae-stroncea I think it's due to the out-of-order events, but not sure. I still have a lot of 0-duration events and unexpected gaps in the timeline.

ErikBjare avatar Feb 21 '21 09:02 ErikBjare