Hi all,
I've tracked down an unexplained EL phenomenon that surfaced in our stats as a false trend in our global stats.
The data I'm looking at specifically is coming from Media Viewer's MultimediaViewerNetworkPerformance_* tables.
Have a look at this graph: https://docs.google.com/spreadsheets/d/1PJsyzAyj74dctGCl4-09L7LS4AMZRh57G56X... the big change is on Jan 7th/8th
It shows how many EL events we've recorded, per client-reported country, over the last 90 days. The sampling factor we use has been constant for each wiki over that period. Thus, the distribution shouldn't evolve drastically, aside from seasonal/local trends. Besides the Ukraine spike on a particular date (probably related to world events), the graph before Jan 7th looks like what you would expect. Then, following the outage that happened on Jan 7th, not only the balance is completely changed, but it evolves over time (the US and China are keeping "higher than normal" levels, while the rest seems to slide down lower than pre-7th quantities), showing me that something strange is happening and is probably unresolved.
This balance shifting over time is really problematic for tracking Media Viewer client-side network performance, because Chinese traffic suddenly accounting for a bigger or smaller share of the overall recorded events creates big swings in the global averages/percentiles (since network performance in China is bad).
Gilles:
This event has a "pretty" constant rate of input: http://graphite.wikimedia.org/render/?width=588&height=311&_salt=142...
And as far as I can see it has not changed (greatly) before and after the 7th. Does this throughput rate match what you see on the database? If so, I would say db matches incoming stream. Now, if it doesn't (somehow the db has less data) we might have a problem. However, dropped events when inserting on the db will affect all countries equally so I doubt these will be the source of the discrepancy.
Are there a bigger number of events that might not be validating for other wikis versus China? Logs are at: stat1002:/a/eventlogging/archive and the all-events log will have every single one of your events received. Please note that events are not inserted right away when received, there is a buffer of couple minutes.
This balance shifting over time is really problematic for tracking Media
Viewer client-side network performance, because Chinese >traffic suddenly accounting for a bigger or smaller share of the overall recorded events creates big swings in the global >averages/percentiles (since network performance in China is bad).
Wouldn't this happen if your product is "more used" in china than elsewhere? If you are counting "absolute" values you will be always skewed to the biggest dataset unless you are doing some kind of scaling.
Thanks,
Nuria
On Wed, Jan 28, 2015 at 4:09 PM, Gilles Dubuc gilles@wikimedia.org wrote:
Hi all,
I've tracked down an unexplained EL phenomenon that surfaced in our stats as a false trend in our global stats.
The data I'm looking at specifically is coming from Media Viewer's MultimediaViewerNetworkPerformance_* tables.
Have a look at this graph: https://docs.google.com/spreadsheets/d/1PJsyzAyj74dctGCl4-09L7LS4AMZRh57G56X... the big change is on Jan 7th/8th
It shows how many EL events we've recorded, per client-reported country, over the last 90 days. The sampling factor we use has been constant for each wiki over that period. Thus, the distribution shouldn't evolve drastically, aside from seasonal/local trends. Besides the Ukraine spike on a particular date (probably related to world events), the graph before Jan 7th looks like what you would expect. Then, following the outage that happened on Jan 7th, not only the balance is completely changed, but it evolves over time (the US and China are keeping "higher than normal" levels, while the rest seems to slide down lower than pre-7th quantities), showing me that something strange is happening and is probably unresolved.
This balance shifting over time is really problematic for tracking Media Viewer client-side network performance, because Chinese traffic suddenly accounting for a bigger or smaller share of the overall recorded events creates big swings in the global averages/percentiles (since network performance in China is bad).
Analytics mailing list Analytics@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/analytics
Does this throughput rate match what you see on the database?
It's hard to tell, because I can't infer how many events per day are generated based on what you're showing me. It depends on the granularity of the curve's rendering. Even if I knew what the numbers going up to 6.2 on the left represent, it still wouldn't tell me how many per hour/per day are recorded there.
Are there a bigger number of events that might not be validating for other
wikis versus China?
Are you talking about syntactically incorrect events that don't pass the schema check?
Wouldn't this happen if your product is "more used" in china than elsewhere?
Sure, but that doesn't really matter, because global trends would evolve slowly. The point of tracking the network performance statistics worldwide, despite their very uneven distribution, is to immediately spot when something very wrong happens. We also track the same stats per wiki, and per country (albeit not on a timeline at this point for the per-country ones). The bottom line is that the per-country share of recorded EL events shouldn't vary wildly like that.
Logs are at: stat1002:/a/eventlogging/
gilles@stat1003:~/20150120$ cat all-events.log-20150120 | grep ""clientValidated": true" | grep -c ""schema": "MultimediaViewerNetworkPerformance"" 330061
And in the DB across the tables that have "active" versions, I get a total of 31 + 327867 = 327898 events recorded
A difference of 2000ish events, might not be a real difference since the date cutoff probably differs between the log file and the timestamp contained in its entries.
Now, looking at an earlier date, when things seemed to be stable in terms of country-based sampling:
gilles@stat1003:~/20150103$ cat all-events.log-20150103 | grep ""clientValidated": true" | grep -c ""schema": "MultimediaViewerNetworkPerformance"" 287712
And in the DB, a total of 5 + 289461 = 289466
So far it does look like everything is making it to the DB, I'll keep investigating tomorrow.
On Wed, Jan 28, 2015 at 5:43 PM, Nuria Ruiz nuria@wikimedia.org wrote:
Gilles:
This event has a "pretty" constant rate of input: http://graphite.wikimedia.org/render/?width=588&height=311&_salt=142...
And as far as I can see it has not changed (greatly) before and after the 7th. Does this throughput rate match what you see on the database? If so, I would say db matches incoming stream. Now, if it doesn't (somehow the db has less data) we might have a problem. However, dropped events when inserting on the db will affect all countries equally so I doubt these will be the source of the discrepancy.
Are there a bigger number of events that might not be validating for other wikis versus China? Logs are at: stat1002:/a/eventlogging/archive and the all-events log will have every single one of your events received. Please note that events are not inserted right away when received, there is a buffer of couple minutes.
This balance shifting over time is really problematic for tracking Media
Viewer client-side network performance, because Chinese >traffic suddenly accounting for a bigger or smaller share of the overall recorded events creates big swings in the global >averages/percentiles (since network performance in China is bad).
Wouldn't this happen if your product is "more used" in china than elsewhere? If you are counting "absolute" values you will be always skewed to the biggest dataset unless you are doing some kind of scaling.
Thanks,
Nuria
On Wed, Jan 28, 2015 at 4:09 PM, Gilles Dubuc gilles@wikimedia.org wrote:
Hi all,
I've tracked down an unexplained EL phenomenon that surfaced in our stats as a false trend in our global stats.
The data I'm looking at specifically is coming from Media Viewer's MultimediaViewerNetworkPerformance_* tables.
Have a look at this graph: https://docs.google.com/spreadsheets/d/1PJsyzAyj74dctGCl4-09L7LS4AMZRh57G56X... the big change is on Jan 7th/8th
It shows how many EL events we've recorded, per client-reported country, over the last 90 days. The sampling factor we use has been constant for each wiki over that period. Thus, the distribution shouldn't evolve drastically, aside from seasonal/local trends. Besides the Ukraine spike on a particular date (probably related to world events), the graph before Jan 7th looks like what you would expect. Then, following the outage that happened on Jan 7th, not only the balance is completely changed, but it evolves over time (the US and China are keeping "higher than normal" levels, while the rest seems to slide down lower than pre-7th quantities), showing me that something strange is happening and is probably unresolved.
This balance shifting over time is really problematic for tracking Media Viewer client-side network performance, because Chinese traffic suddenly accounting for a bigger or smaller share of the overall recorded events creates big swings in the global averages/percentiles (since network performance in China is bad).
Analytics mailing list Analytics@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/analytics
Analytics mailing list Analytics@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/analytics
Looking specifically at China,
CN on Jan 3rd: 9103 in log file, 9415 in DB CN on Jan 20th: 13816 in log file, 13586 in DB
This is further confirmation that EL seems to be fine. Thanks for pointing me in the direction of the raw logs, I didn't know where they were. I'll post an update when we've found the source of this issue.
On Wed, Jan 28, 2015 at 6:20 PM, Gilles Dubuc gilles@wikimedia.org wrote:
Does this throughput rate match what you see on the database?
It's hard to tell, because I can't infer how many events per day are generated based on what you're showing me. It depends on the granularity of the curve's rendering. Even if I knew what the numbers going up to 6.2 on the left represent, it still wouldn't tell me how many per hour/per day are recorded there.
Are there a bigger number of events that might not be validating for other
wikis versus China?
Are you talking about syntactically incorrect events that don't pass the schema check?
Wouldn't this happen if your product is "more used" in china than
elsewhere?
Sure, but that doesn't really matter, because global trends would evolve slowly. The point of tracking the network performance statistics worldwide, despite their very uneven distribution, is to immediately spot when something very wrong happens. We also track the same stats per wiki, and per country (albeit not on a timeline at this point for the per-country ones). The bottom line is that the per-country share of recorded EL events shouldn't vary wildly like that.
Logs are at: stat1002:/a/eventlogging/
gilles@stat1003:~/20150120$ cat all-events.log-20150120 | grep ""clientValidated": true" | grep -c ""schema": "MultimediaViewerNetworkPerformance"" 330061
And in the DB across the tables that have "active" versions, I get a total of 31 + 327867 = 327898 events recorded
A difference of 2000ish events, might not be a real difference since the date cutoff probably differs between the log file and the timestamp contained in its entries.
Now, looking at an earlier date, when things seemed to be stable in terms of country-based sampling:
gilles@stat1003:~/20150103$ cat all-events.log-20150103 | grep ""clientValidated": true" | grep -c ""schema": "MultimediaViewerNetworkPerformance"" 287712
And in the DB, a total of 5 + 289461 = 289466
So far it does look like everything is making it to the DB, I'll keep investigating tomorrow.
On Wed, Jan 28, 2015 at 5:43 PM, Nuria Ruiz nuria@wikimedia.org wrote:
Gilles:
This event has a "pretty" constant rate of input: http://graphite.wikimedia.org/render/?width=588&height=311&_salt=142...
And as far as I can see it has not changed (greatly) before and after the 7th. Does this throughput rate match what you see on the database? If so, I would say db matches incoming stream. Now, if it doesn't (somehow the db has less data) we might have a problem. However, dropped events when inserting on the db will affect all countries equally so I doubt these will be the source of the discrepancy.
Are there a bigger number of events that might not be validating for other wikis versus China? Logs are at: stat1002:/a/eventlogging/archive and the all-events log will have every single one of your events received. Please note that events are not inserted right away when received, there is a buffer of couple minutes.
This balance shifting over time is really problematic for tracking
Media Viewer client-side network performance, because Chinese >traffic suddenly accounting for a bigger or smaller share of the overall recorded events creates big swings in the global >averages/percentiles (since network performance in China is bad).
Wouldn't this happen if your product is "more used" in china than elsewhere? If you are counting "absolute" values you will be always skewed to the biggest dataset unless you are doing some kind of scaling.
Thanks,
Nuria
On Wed, Jan 28, 2015 at 4:09 PM, Gilles Dubuc gilles@wikimedia.org wrote:
Hi all,
I've tracked down an unexplained EL phenomenon that surfaced in our stats as a false trend in our global stats.
The data I'm looking at specifically is coming from Media Viewer's MultimediaViewerNetworkPerformance_* tables.
Have a look at this graph: https://docs.google.com/spreadsheets/d/1PJsyzAyj74dctGCl4-09L7LS4AMZRh57G56X... the big change is on Jan 7th/8th
It shows how many EL events we've recorded, per client-reported country, over the last 90 days. The sampling factor we use has been constant for each wiki over that period. Thus, the distribution shouldn't evolve drastically, aside from seasonal/local trends. Besides the Ukraine spike on a particular date (probably related to world events), the graph before Jan 7th looks like what you would expect. Then, following the outage that happened on Jan 7th, not only the balance is completely changed, but it evolves over time (the US and China are keeping "higher than normal" levels, while the rest seems to slide down lower than pre-7th quantities), showing me that something strange is happening and is probably unresolved.
This balance shifting over time is really problematic for tracking Media Viewer client-side network performance, because Chinese traffic suddenly accounting for a bigger or smaller share of the overall recorded events creates big swings in the global averages/percentiles (since network performance in China is bad).
Analytics mailing list Analytics@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/analytics
Analytics mailing list Analytics@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/analytics
I think I've found where this is coming from. Nothing to do with EL:
- When Media Viewer was launched to production, we forgot about our list of beta sites in the config repo and as a result, wikis that had not been through the beta (Chinese Wikipedia being one of them) ended up being sampled 100 times more than all the other production wikis for this particular metrics (network performance). Which made China, where network performance is particularly bad, overrepresented in the global figures. - On Jan 7th the Timing-Allow-Origin: * header started being served for all images. In itself it should have only meant that our performance logging had more complete records, since the presence of the timing data wasn't a prerequisite in our code to recording a hit. So in itself that doesn't explain the spike of sampled events for that metrics. - In our code there was a line specifically filtering out hits based on timing data, when it believed the image load to be a local cache hit. In think that's the main source of the issue. I suspect that when CORS policies aren't in place, this code (which checked that a certain timing value was set to 0) wrongly believed those to be local cache hits and didn't send them to EL when it should have. Essentially because of the CORS situation in production we'd been accidentally suppressing all image performance events for people with recent browsers, and only recording browsers that don't support the timing APIs. Since we haven't really used the detailed timing data yet, this went unnoticed.
The header being served on 7th suddenly "unlocked" that timing data and suddenly a large amount of events that were previously stopped at the gate on the client side, based on a wrong condition, started flowing into EL. And the imbalance we had because of the sampling rate config issue made this very visible because China, with its very slow speed, was taking a much larger share of the global stats than it should have.
So basically 3 separate bugs combined caused this phenomenon. I think the lesson learned, which we actually applied to the rest of that performance code, is that we're better off not suppressing the client data as long as a user/hit is sampled and we should rather filter the data based on the recorded values later in SQL.
Today I'm going to double-check that when CORS policies are missing timing data does have a 0 value that looks like a local cache hit, if I don't post an update to this thread, my assumptions were correct.
On Wed, Jan 28, 2015 at 8:33 PM, Gilles Dubuc gilles@wikimedia.org wrote:
Looking specifically at China,
CN on Jan 3rd: 9103 in log file, 9415 in DB CN on Jan 20th: 13816 in log file, 13586 in DB
This is further confirmation that EL seems to be fine. Thanks for pointing me in the direction of the raw logs, I didn't know where they were. I'll post an update when we've found the source of this issue.
On Wed, Jan 28, 2015 at 6:20 PM, Gilles Dubuc gilles@wikimedia.org wrote:
Does this throughput rate match what you see on the database?
It's hard to tell, because I can't infer how many events per day are generated based on what you're showing me. It depends on the granularity of the curve's rendering. Even if I knew what the numbers going up to 6.2 on the left represent, it still wouldn't tell me how many per hour/per day are recorded there.
Are there a bigger number of events that might not be validating for
other wikis versus China?
Are you talking about syntactically incorrect events that don't pass the schema check?
Wouldn't this happen if your product is "more used" in china than
elsewhere?
Sure, but that doesn't really matter, because global trends would evolve slowly. The point of tracking the network performance statistics worldwide, despite their very uneven distribution, is to immediately spot when something very wrong happens. We also track the same stats per wiki, and per country (albeit not on a timeline at this point for the per-country ones). The bottom line is that the per-country share of recorded EL events shouldn't vary wildly like that.
Logs are at: stat1002:/a/eventlogging/
gilles@stat1003:~/20150120$ cat all-events.log-20150120 | grep ""clientValidated": true" | grep -c ""schema": "MultimediaViewerNetworkPerformance"" 330061
And in the DB across the tables that have "active" versions, I get a total of 31 + 327867 = 327898 events recorded
A difference of 2000ish events, might not be a real difference since the date cutoff probably differs between the log file and the timestamp contained in its entries.
Now, looking at an earlier date, when things seemed to be stable in terms of country-based sampling:
gilles@stat1003:~/20150103$ cat all-events.log-20150103 | grep ""clientValidated": true" | grep -c ""schema": "MultimediaViewerNetworkPerformance"" 287712
And in the DB, a total of 5 + 289461 = 289466
So far it does look like everything is making it to the DB, I'll keep investigating tomorrow.
On Wed, Jan 28, 2015 at 5:43 PM, Nuria Ruiz nuria@wikimedia.org wrote:
Gilles:
This event has a "pretty" constant rate of input: http://graphite.wikimedia.org/render/?width=588&height=311&_salt=142...
And as far as I can see it has not changed (greatly) before and after the 7th. Does this throughput rate match what you see on the database? If so, I would say db matches incoming stream. Now, if it doesn't (somehow the db has less data) we might have a problem. However, dropped events when inserting on the db will affect all countries equally so I doubt these will be the source of the discrepancy.
Are there a bigger number of events that might not be validating for other wikis versus China? Logs are at: stat1002:/a/eventlogging/archive and the all-events log will have every single one of your events received. Please note that events are not inserted right away when received, there is a buffer of couple minutes.
This balance shifting over time is really problematic for tracking
Media Viewer client-side network performance, because Chinese >traffic suddenly accounting for a bigger or smaller share of the overall recorded events creates big swings in the global >averages/percentiles (since network performance in China is bad).
Wouldn't this happen if your product is "more used" in china than elsewhere? If you are counting "absolute" values you will be always skewed to the biggest dataset unless you are doing some kind of scaling.
Thanks,
Nuria
On Wed, Jan 28, 2015 at 4:09 PM, Gilles Dubuc gilles@wikimedia.org wrote:
Hi all,
I've tracked down an unexplained EL phenomenon that surfaced in our stats as a false trend in our global stats.
The data I'm looking at specifically is coming from Media Viewer's MultimediaViewerNetworkPerformance_* tables.
Have a look at this graph: https://docs.google.com/spreadsheets/d/1PJsyzAyj74dctGCl4-09L7LS4AMZRh57G56X... the big change is on Jan 7th/8th
It shows how many EL events we've recorded, per client-reported country, over the last 90 days. The sampling factor we use has been constant for each wiki over that period. Thus, the distribution shouldn't evolve drastically, aside from seasonal/local trends. Besides the Ukraine spike on a particular date (probably related to world events), the graph before Jan 7th looks like what you would expect. Then, following the outage that happened on Jan 7th, not only the balance is completely changed, but it evolves over time (the US and China are keeping "higher than normal" levels, while the rest seems to slide down lower than pre-7th quantities), showing me that something strange is happening and is probably unresolved.
This balance shifting over time is really problematic for tracking Media Viewer client-side network performance, because Chinese traffic suddenly accounting for a bigger or smaller share of the overall recorded events creates big swings in the global averages/percentiles (since network performance in China is bad).
Analytics mailing list Analytics@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/analytics
Analytics mailing list Analytics@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/analytics
jsfiddle confirming my hunch about CORS and the misguided conditional: http://jsfiddle.net/2ycra7y0/4/
On Thu, Jan 29, 2015 at 10:00 AM, Gilles Dubuc gilles@wikimedia.org wrote:
I think I've found where this is coming from. Nothing to do with EL:
- When Media Viewer was launched to production, we forgot about our list
of beta sites in the config repo and as a result, wikis that had not been through the beta (Chinese Wikipedia being one of them) ended up being sampled 100 times more than all the other production wikis for this particular metrics (network performance). Which made China, where network performance is particularly bad, overrepresented in the global figures.
- On Jan 7th the Timing-Allow-Origin: * header started being served for
all images. In itself it should have only meant that our performance logging had more complete records, since the presence of the timing data wasn't a prerequisite in our code to recording a hit. So in itself that doesn't explain the spike of sampled events for that metrics.
- In our code there was a line specifically filtering out hits based on
timing data, when it believed the image load to be a local cache hit. In think that's the main source of the issue. I suspect that when CORS policies aren't in place, this code (which checked that a certain timing value was set to 0) wrongly believed those to be local cache hits and didn't send them to EL when it should have. Essentially because of the CORS situation in production we'd been accidentally suppressing all image performance events for people with recent browsers, and only recording browsers that don't support the timing APIs. Since we haven't really used the detailed timing data yet, this went unnoticed.
The header being served on 7th suddenly "unlocked" that timing data and suddenly a large amount of events that were previously stopped at the gate on the client side, based on a wrong condition, started flowing into EL. And the imbalance we had because of the sampling rate config issue made this very visible because China, with its very slow speed, was taking a much larger share of the global stats than it should have.
So basically 3 separate bugs combined caused this phenomenon. I think the lesson learned, which we actually applied to the rest of that performance code, is that we're better off not suppressing the client data as long as a user/hit is sampled and we should rather filter the data based on the recorded values later in SQL.
Today I'm going to double-check that when CORS policies are missing timing data does have a 0 value that looks like a local cache hit, if I don't post an update to this thread, my assumptions were correct.
On Wed, Jan 28, 2015 at 8:33 PM, Gilles Dubuc gilles@wikimedia.org wrote:
Looking specifically at China,
CN on Jan 3rd: 9103 in log file, 9415 in DB CN on Jan 20th: 13816 in log file, 13586 in DB
This is further confirmation that EL seems to be fine. Thanks for pointing me in the direction of the raw logs, I didn't know where they were. I'll post an update when we've found the source of this issue.
On Wed, Jan 28, 2015 at 6:20 PM, Gilles Dubuc gilles@wikimedia.org wrote:
Does this throughput rate match what you see on the database?
It's hard to tell, because I can't infer how many events per day are generated based on what you're showing me. It depends on the granularity of the curve's rendering. Even if I knew what the numbers going up to 6.2 on the left represent, it still wouldn't tell me how many per hour/per day are recorded there.
Are there a bigger number of events that might not be validating for
other wikis versus China?
Are you talking about syntactically incorrect events that don't pass the schema check?
Wouldn't this happen if your product is "more used" in china than
elsewhere?
Sure, but that doesn't really matter, because global trends would evolve slowly. The point of tracking the network performance statistics worldwide, despite their very uneven distribution, is to immediately spot when something very wrong happens. We also track the same stats per wiki, and per country (albeit not on a timeline at this point for the per-country ones). The bottom line is that the per-country share of recorded EL events shouldn't vary wildly like that.
Logs are at: stat1002:/a/eventlogging/
gilles@stat1003:~/20150120$ cat all-events.log-20150120 | grep ""clientValidated": true" | grep -c ""schema": "MultimediaViewerNetworkPerformance"" 330061
And in the DB across the tables that have "active" versions, I get a total of 31 + 327867 = 327898 events recorded
A difference of 2000ish events, might not be a real difference since the date cutoff probably differs between the log file and the timestamp contained in its entries.
Now, looking at an earlier date, when things seemed to be stable in terms of country-based sampling:
gilles@stat1003:~/20150103$ cat all-events.log-20150103 | grep ""clientValidated": true" | grep -c ""schema": "MultimediaViewerNetworkPerformance"" 287712
And in the DB, a total of 5 + 289461 = 289466
So far it does look like everything is making it to the DB, I'll keep investigating tomorrow.
On Wed, Jan 28, 2015 at 5:43 PM, Nuria Ruiz nuria@wikimedia.org wrote:
Gilles:
This event has a "pretty" constant rate of input: http://graphite.wikimedia.org/render/?width=588&height=311&_salt=142...
And as far as I can see it has not changed (greatly) before and after the 7th. Does this throughput rate match what you see on the database? If so, I would say db matches incoming stream. Now, if it doesn't (somehow the db has less data) we might have a problem. However, dropped events when inserting on the db will affect all countries equally so I doubt these will be the source of the discrepancy.
Are there a bigger number of events that might not be validating for other wikis versus China? Logs are at: stat1002:/a/eventlogging/archive and the all-events log will have every single one of your events received. Please note that events are not inserted right away when received, there is a buffer of couple minutes.
This balance shifting over time is really problematic for tracking
Media Viewer client-side network performance, because Chinese >traffic suddenly accounting for a bigger or smaller share of the overall recorded events creates big swings in the global >averages/percentiles (since network performance in China is bad).
Wouldn't this happen if your product is "more used" in china than elsewhere? If you are counting "absolute" values you will be always skewed to the biggest dataset unless you are doing some kind of scaling.
Thanks,
Nuria
On Wed, Jan 28, 2015 at 4:09 PM, Gilles Dubuc gilles@wikimedia.org wrote:
Hi all,
I've tracked down an unexplained EL phenomenon that surfaced in our stats as a false trend in our global stats.
The data I'm looking at specifically is coming from Media Viewer's MultimediaViewerNetworkPerformance_* tables.
Have a look at this graph: https://docs.google.com/spreadsheets/d/1PJsyzAyj74dctGCl4-09L7LS4AMZRh57G56X... the big change is on Jan 7th/8th
It shows how many EL events we've recorded, per client-reported country, over the last 90 days. The sampling factor we use has been constant for each wiki over that period. Thus, the distribution shouldn't evolve drastically, aside from seasonal/local trends. Besides the Ukraine spike on a particular date (probably related to world events), the graph before Jan 7th looks like what you would expect. Then, following the outage that happened on Jan 7th, not only the balance is completely changed, but it evolves over time (the US and China are keeping "higher than normal" levels, while the rest seems to slide down lower than pre-7th quantities), showing me that something strange is happening and is probably unresolved.
This balance shifting over time is really problematic for tracking Media Viewer client-side network performance, because Chinese traffic suddenly accounting for a bigger or smaller share of the overall recorded events creates big swings in the global averages/percentiles (since network performance in China is bad).
Analytics mailing list Analytics@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/analytics
Analytics mailing list Analytics@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/analytics
That makes sense Gilles - the "local detection" seems too sophisticated in this case, outliers and stuff like that can be figured out in SQL.
On Thu, Jan 29, 2015 at 2:17 PM, Gilles Dubuc gilles@wikimedia.org wrote:
jsfiddle confirming my hunch about CORS and the misguided conditional: http://jsfiddle.net/2ycra7y0/4/
On Thu, Jan 29, 2015 at 10:00 AM, Gilles Dubuc gilles@wikimedia.org wrote:
I think I've found where this is coming from. Nothing to do with EL:
- When Media Viewer was launched to production, we forgot about our list
of beta sites in the config repo and as a result, wikis that had not been through the beta (Chinese Wikipedia being one of them) ended up being sampled 100 times more than all the other production wikis for this particular metrics (network performance). Which made China, where network performance is particularly bad, overrepresented in the global figures.
- On Jan 7th the Timing-Allow-Origin: * header started being served for
all images. In itself it should have only meant that our performance logging had more complete records, since the presence of the timing data wasn't a prerequisite in our code to recording a hit. So in itself that doesn't explain the spike of sampled events for that metrics.
- In our code there was a line specifically filtering out hits based on
timing data, when it believed the image load to be a local cache hit. In think that's the main source of the issue. I suspect that when CORS policies aren't in place, this code (which checked that a certain timing value was set to 0) wrongly believed those to be local cache hits and didn't send them to EL when it should have. Essentially because of the CORS situation in production we'd been accidentally suppressing all image performance events for people with recent browsers, and only recording browsers that don't support the timing APIs. Since we haven't really used the detailed timing data yet, this went unnoticed.
The header being served on 7th suddenly "unlocked" that timing data and suddenly a large amount of events that were previously stopped at the gate on the client side, based on a wrong condition, started flowing into EL. And the imbalance we had because of the sampling rate config issue made this very visible because China, with its very slow speed, was taking a much larger share of the global stats than it should have.
So basically 3 separate bugs combined caused this phenomenon. I think the lesson learned, which we actually applied to the rest of that performance code, is that we're better off not suppressing the client data as long as a user/hit is sampled and we should rather filter the data based on the recorded values later in SQL.
Today I'm going to double-check that when CORS policies are missing timing data does have a 0 value that looks like a local cache hit, if I don't post an update to this thread, my assumptions were correct.
On Wed, Jan 28, 2015 at 8:33 PM, Gilles Dubuc gilles@wikimedia.org wrote:
Looking specifically at China,
CN on Jan 3rd: 9103 in log file, 9415 in DB CN on Jan 20th: 13816 in log file, 13586 in DB
This is further confirmation that EL seems to be fine. Thanks for pointing me in the direction of the raw logs, I didn't know where they were. I'll post an update when we've found the source of this issue.
On Wed, Jan 28, 2015 at 6:20 PM, Gilles Dubuc gilles@wikimedia.org wrote:
Does this throughput rate match what you see on the database?
It's hard to tell, because I can't infer how many events per day are generated based on what you're showing me. It depends on the granularity of the curve's rendering. Even if I knew what the numbers going up to 6.2 on the left represent, it still wouldn't tell me how many per hour/per day are recorded there.
Are there a bigger number of events that might not be validating for
other wikis versus China?
Are you talking about syntactically incorrect events that don't pass the schema check?
Wouldn't this happen if your product is "more used" in china than
elsewhere?
Sure, but that doesn't really matter, because global trends would evolve slowly. The point of tracking the network performance statistics worldwide, despite their very uneven distribution, is to immediately spot when something very wrong happens. We also track the same stats per wiki, and per country (albeit not on a timeline at this point for the per-country ones). The bottom line is that the per-country share of recorded EL events shouldn't vary wildly like that.
Logs are at: stat1002:/a/eventlogging/
gilles@stat1003:~/20150120$ cat all-events.log-20150120 | grep ""clientValidated": true" | grep -c ""schema": "MultimediaViewerNetworkPerformance"" 330061
And in the DB across the tables that have "active" versions, I get a total of 31 + 327867 = 327898 events recorded
A difference of 2000ish events, might not be a real difference since the date cutoff probably differs between the log file and the timestamp contained in its entries.
Now, looking at an earlier date, when things seemed to be stable in terms of country-based sampling:
gilles@stat1003:~/20150103$ cat all-events.log-20150103 | grep ""clientValidated": true" | grep -c ""schema": "MultimediaViewerNetworkPerformance"" 287712
And in the DB, a total of 5 + 289461 = 289466
So far it does look like everything is making it to the DB, I'll keep investigating tomorrow.
On Wed, Jan 28, 2015 at 5:43 PM, Nuria Ruiz nuria@wikimedia.org wrote:
Gilles:
This event has a "pretty" constant rate of input: http://graphite.wikimedia.org/render/?width=588&height=311&_salt=142...
And as far as I can see it has not changed (greatly) before and after the 7th. Does this throughput rate match what you see on the database? If so, I would say db matches incoming stream. Now, if it doesn't (somehow the db has less data) we might have a problem. However, dropped events when inserting on the db will affect all countries equally so I doubt these will be the source of the discrepancy.
Are there a bigger number of events that might not be validating for other wikis versus China? Logs are at: stat1002:/a/eventlogging/archive and the all-events log will have every single one of your events received. Please note that events are not inserted right away when received, there is a buffer of couple minutes.
This balance shifting over time is really problematic for tracking
Media Viewer client-side network performance, because Chinese >traffic suddenly accounting for a bigger or smaller share of the overall recorded events creates big swings in the global >averages/percentiles (since network performance in China is bad).
Wouldn't this happen if your product is "more used" in china than elsewhere? If you are counting "absolute" values you will be always skewed to the biggest dataset unless you are doing some kind of scaling.
Thanks,
Nuria
On Wed, Jan 28, 2015 at 4:09 PM, Gilles Dubuc gilles@wikimedia.org wrote:
Hi all,
I've tracked down an unexplained EL phenomenon that surfaced in our stats as a false trend in our global stats.
The data I'm looking at specifically is coming from Media Viewer's MultimediaViewerNetworkPerformance_* tables.
Have a look at this graph: https://docs.google.com/spreadsheets/d/1PJsyzAyj74dctGCl4-09L7LS4AMZRh57G56X... the big change is on Jan 7th/8th
It shows how many EL events we've recorded, per client-reported country, over the last 90 days. The sampling factor we use has been constant for each wiki over that period. Thus, the distribution shouldn't evolve drastically, aside from seasonal/local trends. Besides the Ukraine spike on a particular date (probably related to world events), the graph before Jan 7th looks like what you would expect. Then, following the outage that happened on Jan 7th, not only the balance is completely changed, but it evolves over time (the US and China are keeping "higher than normal" levels, while the rest seems to slide down lower than pre-7th quantities), showing me that something strange is happening and is probably unresolved.
This balance shifting over time is really problematic for tracking Media Viewer client-side network performance, because Chinese traffic suddenly accounting for a bigger or smaller share of the overall recorded events creates big swings in the global averages/percentiles (since network performance in China is bad).
Analytics mailing list Analytics@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/analytics
Analytics mailing list Analytics@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/analytics
Analytics mailing list Analytics@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/analytics
Super good job. It was probably not easy to figure out that perfect storm of events.
So basically 3 separate bugs combined caused this phenomenon. I think the
lesson learned, which we actually applied to the rest >of that performance code, is that we're better off not suppressing the client data as long as a user/hit is sampled and we should >rather filter the data based on the recorded values later in SQL. Much Agreed. When loading perf data the standard is to expect to distinct distributions for clients with hot and cold cache.
On Thu, Jan 29, 2015 at 12:22 PM, Dan Andreescu dandreescu@wikimedia.org wrote:
That makes sense Gilles - the "local detection" seems too sophisticated in this case, outliers and stuff like that can be figured out in SQL.
On Thu, Jan 29, 2015 at 2:17 PM, Gilles Dubuc gilles@wikimedia.org wrote:
jsfiddle confirming my hunch about CORS and the misguided conditional: http://jsfiddle.net/2ycra7y0/4/
On Thu, Jan 29, 2015 at 10:00 AM, Gilles Dubuc gilles@wikimedia.org wrote:
I think I've found where this is coming from. Nothing to do with EL:
- When Media Viewer was launched to production, we forgot about our list
of beta sites in the config repo and as a result, wikis that had not been through the beta (Chinese Wikipedia being one of them) ended up being sampled 100 times more than all the other production wikis for this particular metrics (network performance). Which made China, where network performance is particularly bad, overrepresented in the global figures.
- On Jan 7th the Timing-Allow-Origin: * header started being served for
all images. In itself it should have only meant that our performance logging had more complete records, since the presence of the timing data wasn't a prerequisite in our code to recording a hit. So in itself that doesn't explain the spike of sampled events for that metrics.
- In our code there was a line specifically filtering out hits based on
timing data, when it believed the image load to be a local cache hit. In think that's the main source of the issue. I suspect that when CORS policies aren't in place, this code (which checked that a certain timing value was set to 0) wrongly believed those to be local cache hits and didn't send them to EL when it should have. Essentially because of the CORS situation in production we'd been accidentally suppressing all image performance events for people with recent browsers, and only recording browsers that don't support the timing APIs. Since we haven't really used the detailed timing data yet, this went unnoticed.
The header being served on 7th suddenly "unlocked" that timing data and suddenly a large amount of events that were previously stopped at the gate on the client side, based on a wrong condition, started flowing into EL. And the imbalance we had because of the sampling rate config issue made this very visible because China, with its very slow speed, was taking a much larger share of the global stats than it should have.
So basically 3 separate bugs combined caused this phenomenon. I think the lesson learned, which we actually applied to the rest of that performance code, is that we're better off not suppressing the client data as long as a user/hit is sampled and we should rather filter the data based on the recorded values later in SQL.
Today I'm going to double-check that when CORS policies are missing timing data does have a 0 value that looks like a local cache hit, if I don't post an update to this thread, my assumptions were correct.
On Wed, Jan 28, 2015 at 8:33 PM, Gilles Dubuc gilles@wikimedia.org wrote:
Looking specifically at China,
CN on Jan 3rd: 9103 in log file, 9415 in DB CN on Jan 20th: 13816 in log file, 13586 in DB
This is further confirmation that EL seems to be fine. Thanks for pointing me in the direction of the raw logs, I didn't know where they were. I'll post an update when we've found the source of this issue.
On Wed, Jan 28, 2015 at 6:20 PM, Gilles Dubuc gilles@wikimedia.org wrote:
Does this throughput rate match what you see on the database?
It's hard to tell, because I can't infer how many events per day are generated based on what you're showing me. It depends on the granularity of the curve's rendering. Even if I knew what the numbers going up to 6.2 on the left represent, it still wouldn't tell me how many per hour/per day are recorded there.
Are there a bigger number of events that might not be validating for
other wikis versus China?
Are you talking about syntactically incorrect events that don't pass the schema check?
Wouldn't this happen if your product is "more used" in china than
elsewhere?
Sure, but that doesn't really matter, because global trends would evolve slowly. The point of tracking the network performance statistics worldwide, despite their very uneven distribution, is to immediately spot when something very wrong happens. We also track the same stats per wiki, and per country (albeit not on a timeline at this point for the per-country ones). The bottom line is that the per-country share of recorded EL events shouldn't vary wildly like that.
Logs are at: stat1002:/a/eventlogging/
gilles@stat1003:~/20150120$ cat all-events.log-20150120 | grep ""clientValidated": true" | grep -c ""schema": "MultimediaViewerNetworkPerformance"" 330061
And in the DB across the tables that have "active" versions, I get a total of 31 + 327867 = 327898 events recorded
A difference of 2000ish events, might not be a real difference since the date cutoff probably differs between the log file and the timestamp contained in its entries.
Now, looking at an earlier date, when things seemed to be stable in terms of country-based sampling:
gilles@stat1003:~/20150103$ cat all-events.log-20150103 | grep ""clientValidated": true" | grep -c ""schema": "MultimediaViewerNetworkPerformance"" 287712
And in the DB, a total of 5 + 289461 = 289466
So far it does look like everything is making it to the DB, I'll keep investigating tomorrow.
On Wed, Jan 28, 2015 at 5:43 PM, Nuria Ruiz nuria@wikimedia.org wrote:
Gilles:
This event has a "pretty" constant rate of input: http://graphite.wikimedia.org/render/?width=588&height=311&_salt=142...
And as far as I can see it has not changed (greatly) before and after the 7th. Does this throughput rate match what you see on the database? If so, I would say db matches incoming stream. Now, if it doesn't (somehow the db has less data) we might have a problem. However, dropped events when inserting on the db will affect all countries equally so I doubt these will be the source of the discrepancy.
Are there a bigger number of events that might not be validating for other wikis versus China? Logs are at: stat1002:/a/eventlogging/archive and the all-events log will have every single one of your events received. Please note that events are not inserted right away when received, there is a buffer of couple minutes.
>This balance shifting over time is really problematic for tracking Media Viewer client-side network performance, because Chinese >traffic suddenly accounting for a bigger or smaller share of the overall recorded events creates big swings in the global >averages/percentiles (since network performance in China is bad).
Wouldn't this happen if your product is "more used" in china than elsewhere? If you are counting "absolute" values you will be always skewed to the biggest dataset unless you are doing some kind of scaling.
Thanks,
Nuria
On Wed, Jan 28, 2015 at 4:09 PM, Gilles Dubuc gilles@wikimedia.org wrote:
> Hi all, > > I've tracked down an unexplained EL phenomenon that surfaced in our > stats as a false trend in our global stats. > > The data I'm looking at specifically is coming from Media Viewer's > MultimediaViewerNetworkPerformance_* tables. > > Have a look at this graph: > https://docs.google.com/spreadsheets/d/1PJsyzAyj74dctGCl4-09L7LS4AMZRh57G56X... > the big change is on Jan 7th/8th > > It shows how many EL events we've recorded, per client-reported > country, over the last 90 days. The sampling factor we use has been > constant for each wiki over that period. Thus, the distribution shouldn't > evolve drastically, aside from seasonal/local trends. Besides the Ukraine > spike on a particular date (probably related to world events), the graph > before Jan 7th looks like what you would expect. Then, following the outage > that happened on Jan 7th, not only the balance is completely changed, but > it evolves over time (the US and China are keeping "higher than normal" > levels, while the rest seems to slide down lower than pre-7th quantities), > showing me that something strange is happening and is probably unresolved. > > This balance shifting over time is really problematic for tracking > Media Viewer client-side network performance, because Chinese traffic > suddenly accounting for a bigger or smaller share of the overall recorded > events creates big swings in the global averages/percentiles (since network > performance in China is bad). > > _______________________________________________ > Analytics mailing list > Analytics@lists.wikimedia.org > https://lists.wikimedia.org/mailman/listinfo/analytics > >
Analytics mailing list Analytics@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/analytics
Analytics mailing list Analytics@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/analytics
Analytics mailing list Analytics@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/analytics