Significant differences between reporting of aw-server and aw-server-rust

Question

Significant differences between reporting of aw-server and aw-server-rust

nicolae-stroncea opened this issue 4 years ago · 31 comments

I looked at my events for a day a month ago, and there are a couple of significant differences between what aw-server-rust and what aw-server reports.

Not sure if it's due to the migration or one/multiple transform issues.

Individual application time:

Application	aw-server	aw-server-rust
Firefox	48m26s	46m38s
Chromium	38m41s	9m31s
Gedit	9m	8m57s
Guake	1m	1m35s
Unknown	14s	15s

Note: Individual application time seems to vary everywhere, and in all of the tabs.

Total Active time

aw-server	aw-server-rust
1h 38min	1hr 6 min

Active browser time in Browser tab:

aw-server	aw-server-rust
1 hr 21 min	52 min

Another potential bug: If you sum up ALL of the times for each browser domain, they won't be equal to the total active browser time for aw-server-rust. This issue doesn't occur for aw-server.

Top categories amounts are also all very different between the 2 servers. This however, is expected given point 1.
Timelines look the same(from a high level view)

OS: Fedora 32, Gnome 3.36, Xorg

Answer 1 · 2020-06-26T06:11:53.000Z

Are you running the latest master or the last pre-built binary from 0.9.2?
And did you do this while running both at the same time or was if after migrating from one to the other?

Individual application time:

The individual application time for chromium worries me a lot, the other ones seem to be fine.

Total Active time

Active browser time in Browser tab

The total active time query is pretty simple, shouldn't be too hard to find out where they differ here.
The flooding algorithm are quite different between aw-server-python and aw-server-rust, but they are supposed to have the same output so somethings likely wrong there is my guess.

Not really sure why they are so mure more different in browser active time than afk active time though.

Another potential bug: If you sum up ALL of the times for each browser domain, they won't be equal to the total active browser time for aw-server-rust. This issue doesn't occur for aw-server.

Definitely an issue as all browser events have a domain.

Timelines look the same(from a high level view)

The timelines do not do any transformations at all and only shows raw events, so that's good at least.

Answer 2 · 2020-06-26T06:34:31.000Z

I have completely different results (but don't use chromium, so that might make a difference? Maybe? I don't know)

Exported my main database (from aw-server-rust) and imported it into aw-server-python and here are my results (running aw-server-rust master, aw-server-python master and aw-webui master on both):

rust/python

Total active time: 4h / 4h 1s
firefox usage for that day: 2h 13m 56s / 2h 14m 11s
URxvt usage for that day: 1h 38m 12s / 1h 38m 8s
active browser time for that day: 2h 13m 52s / 2h 14m 7s
time on domain github.com: 1h 21m 24s / 1h 24m 6s
Active editor time: 56m 3s / 56m 31s

notes:

aw-server-rust seems to discard the domain "127.0.0.1:27180"
I have not calculated the total of the domains, but they certainly seem to be way off (but seem to do so on both aw-server-python and aw-server-rust, aw-webui issue?)

So i definitely need to look into why the total of the domains are way off at least, that one is critical (possibly caused by ActivityWatch/aw-webui#203 maybe?)

Answer 3 · 2020-06-26T06:54:16.000Z

I calculated how much the domain time was off and it was about 12% off (2h14m total, manually summing domains was 1h57m).
It is the same on both aw-server-rust and aw-server-python.

Answer 4 · 2020-06-27T17:50:37.000Z

Are you running the latest master or the last pre-built binary from 0.9.2?
And did you do this while running both at the same time or was if after migrating from one to the other?

So i definitely need to look into why the total of the domains are way off at least, that one is critical (possibly caused by ActivityWatch/aw-webui#203 maybe?)

I'm running it on 0.92 without any changes/customizations, therefore I don't think it's vityWatch/aw-webui#203. I also ran them one at a time to record the changes.

Answer 5 · 2020-06-27T18:18:41.000Z

I compared data on 5 different days.

The biggest difference between apps that weren't Chromium was 3-4 minutes. In your previous comments that didn't surprise you. Why is there a difference at all?
It seems I captured the day where Chromium was misbehaving by complete chance. On the other days Chromium is within a reasonable difference on aw-server-rust and aw-server, so I'm not completely sure it's a Chromium problem, might just be a problem that happened to Chromium in that instance.

Here's the Chromium events reported on that day from Top Applications and Top Browser Domains

Window Title	aw-server	aw-server-rust
Messenger-call Chromium(opened in a new call-specific window(not sure what the term for those are)	10m 7s	1m 36s
Facebook	17m 23s	1m 39s

And then a bunch of others that show up in the top 20? for aw-server but not for aw-server-rust, so their recorded time was less than 1min. These events were (~4min) in aw-server

Answer 6 · 2020-06-27T18:58:36.000Z

I tried to compare weekly aggregations. Here's what I found( I only put the top 4-5):

Week 1:

application	aw-server	aw-server-rust
Total time	27h 3m	24h 22m
Firefox	17h 13 m	15h 31m
Code	4h	3h 14 min
Chromium	50m	48m
Tilix	52 min	47 min

Week 2:

application	aw-server	aw-server-rust
Total time	27h 30m	24h 55m
Firefox	16h 41m	15h 5m
Gedit	6h 2m	5h 28m
Code	1h 2m	1h 2m
Chromium	41m	40 m
Nautilus	40m	35 m

Week 3:

application	aw-server	aw-server-rust
Total time	47h	46h 7m
Firefox	25h 33m	25h 5m
Code	10h 14m	10h 14m
Gedit	5h 40m	5h 37m
Tilix	1h 38m	1h 32 m

Answer 7 · 2020-06-27T19:11:05.000Z

Some more observations:

Previously aw-server-rust migrated all of the events automatically. I deleted all buckets, and instead exported them from aw-server and imported them into aw-server-rust using the Import/Export functionality. The results were identical for aw-server-rust (across the summations for the 3 weeks)
Tried to run aw-server-rust in testing( by calling the aw-server-rust executable with --testingbut it still binds to port 5600. Is this a bug?

Answer 8 · 2020-06-27T20:25:05.000Z

The biggest difference between apps that weren't Chromium was 3-4 minutes. In your previous comments that didn't surprise you. Why is there a difference at all?

The implementations are not identical (even though very similar for most transforms).
Things like the flooding algorithm is completely different but when I made it I think the output should be the same but I'm not certain.
Some bugs are even fixed (such as when fetching events when there are events close to the next day now behaves correctly) and some new ones are likely added but not found yet.
Wasn't the worst one 2 minutes out of 49min? 2min out of for example 49min is about 4% which is indeed more than I expected, but I wouldn't say that I'm surprised.
Not sure why yours are so much more off than mine though, for me for example firefox was 15 seconds different over a total of 2h 14min for example.

I tried to compare weekly aggregations. Here's what I found( I only put the top 4-5):

Week 1 and 2 are on average about 10% off while week 3 is about 2%. I wonder why.

Tried to run aw-server-rust in testing( by calling the aw-server-rust executable with --testingbut it still binds to port 5600. Is this a bug?

It is a bug on 0.9.2 but which is fixed on master. There are lots of changes on aw-server-rust since 0.9.2.

Answer 9 · 2020-06-27T21:14:20.000Z

Wasn't the worst one 2 minutes out of 49min? 2min out of for example 49min is about 4% which is indeed more than I expected, but I wouldn't say that I'm surprised.

In one of my days, aw-server-rust reports github(which was on Firefox) as: 20m 1 s, and aw-server: 23m 21s for Top Browser Domains, which is a 15% difference

Answer 10 · 2020-06-27T21:28:19.000Z

In one of my days, aw-server-rust reports github(which was on Firefox) as: 20m 1 s, and aw-server: 23m 21s for Top Browser Domains, which is a 15% difference

Not worse than for vscode on week 1 which was at 18.75%.
On week 2 and 3 however the same application was perfect.

Answer 11 · 2020-06-27T22:27:39.000Z

I queried the actual databases for the day when Chromium was reported 38 minutes(server) and 9 minutes(server-rust):

Number of events:

Aw-server:
SELECT count(id) FROM eventmodel where timestamp LIKE "2020-06-16%" and datastr LIKE "%Chromium%";
157

Aw-server-rust:
SELECT count(id) FROM events WHERE starttime > 1592265600000000000 and starttime < 1592352000000000000 and data LIKE "%Chromium%";
157

Total time reported by database:

Aw-server-rust
SELECT sum(endtime-starttime) FROM events WHERE starttime > 1592265600000000000 and starttime < 1592352000000000000 and data LIKE "%Chromium%";

4131272999985 nanoseconds = 1hr 8 m 51 s

Aw-server
SELECT sum(duration) FROM eventmodel where timestamp LIKE "2020-06-16%" and datastr LIKE "%Chromium%";

4131.273 seconds = 1hr 8 m 51 s

EDIT: afk-buckets for that day are also identical

Answer 12 · 2020-06-28T08:04:34.000Z

@nicolae-stroncea So with that in mind there's nothing wrong with the migration, but with the query language or the transforms.

So you can instead write a custom query which tests each step and compare between aw-server and aw-server-rust to see where it differs the most.
Here's an example you can put in the query explorer which returns each step, might need some small tweaks though, works on my machine at least

afk_events = query_bucket(find_bucket("aw-watcher-afk_"));
flooded_afk_events = flood(afk_events);

window_events = query_bucket(find_bucket("aw-watcher-window_"));
flooded_window_events = flood(window_events);
window_events_chromium = filter_keyvals(flooded_window_events, "app", ["Chromium"]);

intersected_events = filter_period_intersect(window_events_chromium, filter_keyvals(afk_events, "status", ["not-afk"]));
merged_events = sort_by_duration(merge_events_by_keys(intersected_events, ["app", "title"]));

RETURN = {
    "afk": sum_durations(afk_events),
    "afk_flooded": sum_durations(flooded_afk_events),
    "window": sum_durations(window_events),
    "window_flooded": sum_durations(flooded_window_events),
    "window_chromium": sum_durations(window_events_chromium),
    "intersected_events": sum_durations(intersected_events),
    "merged_events": sum_durations(merged_events)
};

Answer 13 · 2020-06-28T13:04:44.000Z

Don't think the query works for me(everything below is for aw-server):

Interestingly enough, the default query doesn't work at all.

afk_events = query_bucket(find_bucket("aw-watcher-afk_"));
window_events = query_bucket(find_bucket("aw-watcher-window_"));
window_events = filter_period_intersect(window_events, filter_keyvals(afk_events, "status", ["not-afk"]));
merged_events = merge_events_by_keys(window_events, ["app", "title"]);
RETURN = sort_by_duration(merged_events);

I will press the button, and it won't return anything. Checking the developer console, or the aw-server doesn't show anything either

Any ideas on what might be wrong?

Answer 14 · 2020-06-28T15:14:26.000Z

@johan-bjareholt I anonymized all of the data for the day with the big difference between Chrome on aw-server and aw-server-rust, and sent you the buckets on the forum in a PM.

You should be able to directly import the file from the aw-webui

EDIT: To get the exact times as I'm getting, you might also need to set your timezone to America/Toronto (UTC-4)

Answer 15 · 2020-06-28T19:39:06.000Z

@nicolae-stroncea The result looks correct, you just need to select the "Raw JSON" mode as it's not returning events but a total duration in seconds. Sorry for not explaining that.

Answer 16 · 2020-06-28T20:12:56.000Z

And the reason why the default query doesn't work is because you have two window buckets and two afk buckets and the find_bucket command just finds the first one (and one of them is likely the one that is empty). Either replace the double buckets or replace the find_bucket("bucket_") with just "bucket_hostname" and it will work.

Answer 17 · 2020-06-29T02:01:12.000Z

Thanks for the assistance. Here's the results for the day with the Chrome difference:

aw-server:

{
  "afk": 77527.590024,
  "afk_flooded": 77507.327024,
  "window": 23320.294,
  "window_flooded": 23710.941,
  "window_chromium": 0,
  "intersected_events": 0,
  "merged_events": 0
}

aw-server-rust:

{
  "afk": 19803.027,
  "afk_flooded": 17920.446,
  "intersected_events": 0,
  "merged_events": 0,
  "window": 12880.362,
  "window_chromium": 0,
  "window_flooded": 13266.992
}

Answer 18 · 2020-06-29T06:16:51.000Z

I've also already checked the difference. In the query though you have to change the intersect string from "Chromium" to "Chromium-browser".

I'm also looking at it right now, there is something wrong going on with the flooding algorithm which I will be investigating.

Answer 19 · 2020-06-30T05:38:04.000Z

Okay, here's the issue

These two events occur at the exact same timestamp (and overlaps!). Something has gone very wrong with the afk watcher and the flooding algorithm chooses the duration of the shorter one because that's the one second in order because it has a higher ID and was therefore after the first one in the bucket even though they have the same timestamp.

If the shorter one would have arrived at the same timestamp but had been inserted before the long one we would not have noticed the difference because it would only be 10 seconds.

    {
      "data": {
        "status": "not-afk"
      },
      "duration": 1762.192,
      "id": 1095456,
      "timestamp": "2020-06-16T12:06:49.343Z"
    },
    {
      "data": {
        "status": "not-afk"
      },
      "duration": 10.015,
      "id": 1095457,
      "timestamp": "2020-06-16T12:06:49.343Z"
    },

Damn it, I had hoped for some more juicy issue than just a bad watcher :(

Answer 20 · 2020-06-30T05:40:46.000Z

In your example it has actually happened twice though which is interesting. (two events with the same timestamp at 2020-06-16T21:29:58.629Z)

Answer 21 · 2020-06-30T05:48:15.000Z

It's possible to work around it in the transform code, not sure if we want to do that though...

Answer 22 · 2020-06-30T05:48:58.000Z

And according to the heartbeat code it does not seem to be possible to get two events at the same timestamp as then they should be merged which is even more strange?
Will have to write unittests for that.

Answer 23 · 2020-06-30T06:19:06.000Z

Works in aw-server-rust and it's actually a bug in pythons aw-core for aw-server-python where equal timestamps on a heartbeat are not merged. That's silly...

ActivityWatch/aw-core#91
#142

Answer 24 · 2020-07-01T12:29:09.000Z

@johan-bjareholt great to hear you figured out the issue!

You said the bug was in aw-core for aw-server-python. I thought aw-server-rust was the one that underestimated the time to: 9 minutes instead of 39. Or does fixing aw-core fix that issue for aw-server-rust too?

Answer 25 · 2020-07-01T13:28:49.000Z

Just queried my database for similar events:
SELECT count(*), timestamp FROM eventmodel WHERE bucket_id = 5 GROUP BY timestamp HAVING count(*) > 1 ORDER BY timestamp DESC;

and this occured 668 times on my primary(Linux) machine, with events in the same timestamp repeating between 2 and 6 times in the afk bucket. Seems to occur pretty much daily, sometimes 2-3 times a day.

I looked at the other buckets, and found the same problem in all of them, so this doesn't seem to be a watcher specific issue.

I'm not sure how watchers could be triggered twice at the same exact timestamp given that they are polling at specific intervals, so somehow the events must be duplicated? Another possible reason is the queueing mechanism, but I didn't look in the code for it

Answer 26 · 2020-07-01T13:40:33.000Z

The record for the highest number of events all in the same timestamp is for window-watcher, with 56 in the same timestamp, for my Tilix terminal.

Answer 27 · 2020-07-02T06:23:25.000Z

You said the bug was in aw-core for aw-server-python. I thought aw-server-rust was the one that underestimated the time to: 9 minutes instead of 39. Or does fixing aw-core fix that issue for aw-server-rust too?

Well, having events on the exact same millisecond and having events intersecting in a bucket is undefined behavior and the heardbeat implemenetation in aw-server-python created such a case.

The aw-server-python change will fix it for all future heartbeats for aw-server-python, but not for the current ones. So I still need to make a workaround in aw-server-rust because I want everything to be backwards compatible.

Answer 28 · 2020-07-03T12:50:21.000Z

@nicolae-stroncea Could you test with building with #143? I think that should solve the issue

Answer 29 · 2020-07-03T21:52:12.000Z

Issue appears solved. Looked at the data for a couple of weeks, and largest difference between total active time was 10 minutes (across entire week). Similarly largest difference between total weekly active time for apps (was a couple of minutes).

Interestingly enough, sometimes apps differentiated by a couple of minutes, but then different apps differentiated by a similar amount, so it seems like aw-server and aw-server-rust considered different apps to be active occasionally

Answer 30 · 2020-07-03T23:32:21.000Z

Couple of more side-notes before you close the issue:

When building everything with make build, I'm able to start each module from the virtual environment: aw-server, aw-watcher-afk, and aw-watcher-window or all of them with aw-qt. This is not possible for aw-server-rust. To build it, I had to package and then execute it.
Here's the script to anonymize data in case it is ever useful again:

import json
from faker import Faker
fake = Faker()
anonymizer = {}
with open('exported_file.json') as json_file:
    data = json.load(json_file)
    ids = []
    count = 0
    for bucket_name in data['buckets']:
        if(bucket_name.startswith('aw-watcher-web-chrome') or bucket_name.startswith('aw-watcher-web-firefox')):
            print(f"anonymize: {bucket_name} with num events: {len(data['buckets'][bucket_name]['events'])}")   
            # if len(data['buckets'][bucket_name]['events']) > 0:
            #     print(data['buckets'][bucket_name]['events'][0])  
            for event in data['buckets'][bucket_name]['events']:
                key = event['data']['title'] 
                if key not in anonymizer:
                    anonymizer[key] =  fake.sentence(4)
                event['data']['title'] = anonymizer[key]
                
                key = event['data']['url']
                if key not in anonymizer:
                    anonymizer[key] =  fake.uri()
                event['data']['url'] = anonymizer[key]

        elif(bucket_name.startswith('aw-watcher-window_')):
            print(f"anonymize: {bucket_name} with num events: {len(data['buckets'][bucket_name]['events'])}")  
            # if len(data['buckets'][bucket_name]['events']) > 0:
            #     print(data['buckets'][bucket_name]['events'][0])   
            for event in data['buckets'][bucket_name]['events']:
                key = event['data']['title'] 
                if key not in anonymizer:
                    anonymizer[key] =  fake.sentence(4)
                event['data']['title'] = anonymizer[key]
        else:
            print(f"skip: {bucket_name} with num events: {len(data['buckets'][bucket_name]['events'])}")     


with open('anonymized.json', 'w') as outfile:
    json.dump(data, outfile)

Answer 31 · 2020-07-05T10:54:06.000Z

When building everything with make build, I'm able to start each module from the virtual environment: aw-server, aw-watcher-afk, and aw-watcher-window or all of them with aw-qt. This is not possible for aw-server-rust. To build it, I had to package and then execute it.

The virtual environment is only for python applications. If you want aw-server-rust in your path you can install it with "sudo make install" after packaging it.