[04:44:30] Analytics / Tech community metrics: "Age of unreviewed changesets by affiliation" shows negative number of changesets - https://bugzilla.wikimedia.org/70600#c7 (Alvaro) I plan to review all labels and help texts today and next, work on this issue. So expect a solution, or an explanation of the numbers,... [15:15:49] drdee, hewo! [15:15:51] :) [15:16:06] hola [15:16:29] i am poking at sqoopy, btw :) [15:18:16] Analytics / Tech community metrics: "Age of unreviewed changesets by affiliation" shows negative number of changesets - https://bugzilla.wikimedia.org/70600#c8 (Alvaro) Quim, the number of reviews now show the correct number. The main problem was that there are new identities not linked to Unknown.... [15:38:09] qchris: hiya :) [15:38:26] Heya :-) [15:38:47] * qchris is still looking at the alerts from yesterday [15:38:53] alerts? [15:39:31] Run /home/qchris/cluster-scripts/dump_webrequest_status.sh on stat1002 [15:40:01] qchris, eep [15:40:54] qchris, the 28T04 can be explained by kafka zookeepe rproblem again [15:40:56] that happened this weekend [15:41:44] qchris, also, I would really like to make oozie run your script and email a report daily or weekly [15:44:10] ottomata: Back [15:44:16] Ja, totally. [15:44:31] Script needs polishing as you know :-) But yes, the script helps me a lot. [15:44:40] yeah its really nice [15:44:58] I also think that the 28T04 can be explained away with the zookeeper. [15:45:13] 28T14+15 is probably again the race condition. [15:45:30] aye [15:45:31] But I am curious about the 28T18,19,20 [15:45:42] So ... anyways ... you pinged me, sir? [15:46:05] wellllp, i am ready to argue about namign with you whenever, but, i was thinking about sqoop stuff [15:46:12] and wanted to get your opinion real quick. [15:46:17] k [15:46:19] there is an oozie sqoop action [15:46:22] but i'm not sure if we can use it [15:46:28] sorry [15:46:29] should* [15:46:32] we def can. [15:46:34] Does CDH have it? [15:46:36] Ok. [15:46:51] not sure if we should, because, i like using oozie for things that are triggered by datasets [15:46:54] rather than time schedule [15:47:05] for things that are regularly timed, it almost seems better to just use cron [15:47:12] and, for sqoop, i think we [15:47:18] we'd just want to run it every hour, or maybe every day [15:47:19] or something [15:47:51] I basically agree. [15:48:08] But Oozie is also nice when trying to re-run things. [15:48:27] Mhmmm ... that probably does not apply here. [15:48:34] yeah, because you jsut run sqoop [15:48:38] and it will catch you up to date [15:48:42] If one run fails, the next hour's run would do both hours. [15:48:45] each run does not output a regular dataset [15:48:46] yes [15:48:46] Right. [15:48:49] similar to camus [15:48:55] actually, it is analogous to camus here [15:49:00] it is a cron we run to import data into hdfs [15:49:10] I guess it's fine to scoop through cron. [15:49:35] Cron is simpler to set up anyways. [15:49:39] so, i'm picturing a script that takes a config file of a list of database.tables to import, and maybe a mapping of table name to query [15:49:54] hmm [15:49:56] or, hm [15:50:19] maybe multiple scripts. a simple sqoop wrapper (like I wrote for camus) that will avoid launching jobs if they are currently running [15:50:31] like, if there is a plwiki.page import currently rnning, you can't launch another one. [15:50:49] and then, hm, how to schedule imports for specific tables? a cron job for each one? [15:50:49] Sounds involved to me already ... [15:50:50] that will be alot. [15:51:17] If you add that amount of complexity ... wouldn't Oozie pay off? [15:51:18] maybe, a script that takes a mediawiki database name, and just does all the relevant imports for that database? [15:51:30] yeah, it might...a bundle with a coord for each database? [15:51:32] hmmm [15:51:38] Something along those lines. Yes. [15:51:47] maybe...because then we could have a workflow that runs each sqoop action for each table we want [15:52:08] a mediawiki-sqoop workflow [15:52:12] Do we have a rough plan how many tables we want to import? [15:52:23] no, right now i'm only looking at page, and then categorylinks and category [15:52:28] mayyyybe revision eventually, we will see. [15:53:03] Ok. [15:53:06] one of the reasons i was thinking a script instead of oozie, is that we have to be able to store the last imported ID somehow [15:53:14] that is returned by the sqoop output [15:53:33] so, that needs stored and relooked up by the script (or oozie) in for the subsequent sqoop run [15:53:37] to tell it where to start from incrementally [15:53:44] Ok. [15:54:00] i'm sure this is possible to do via oozie, it just might be much more cumbersome [15:54:03] Since Oozie could do that time based ... could we use the timestamp to achiev that? [15:54:20] Like for the run ofr this hour, import from this to that timestamp? [15:54:27] hmmm, we could , but that would be a little hacky, and really only be relevant for records that have updated_at timestamps [15:54:36] True. [15:54:41] for page, at least, and probably many of the records, we will be using the id [15:54:55] But page rows update ... don't they? [15:55:11] yeah they do [15:55:13] (Like ... same id, but the revision number increases) [15:55:14] but there's no updated timestamp [15:55:20] ah yes, but that is revision table [15:55:22] not page table [15:55:40] So storing the id would not help ... would it? [15:55:43] i'm sure page table gets updated too, there are fields like 'page_is_new', and 'page_title' [15:56:03] well, it would help if we don't support updated data...yet : [15:56:04] hm [15:56:09] not sure how to do it other than Id though [15:56:12] since there is not updated timestamp. [15:56:22] or is htere.. [15:56:25] Ironholds: yt? [15:56:26] do you know? [15:56:36] ottomata, I'm here [15:56:45] waddayaneed [15:56:52] is there a way to know when page table record was last updated? [15:56:56] * Ironholds thinks [15:57:00] yes! [15:57:08] page_touched [15:57:12] page_links_updated [15:57:22] https://www.mediawiki.org/wiki/Manual:Page_table [15:57:24] ah, no [15:57:25] oh, page_touced [15:57:27] ? [15:57:40] so, page_touched would include changes we don't care about, unless you're planning on storing revision text [15:57:54] I modify Template:!, and immediately any page that substitutes that template has a new page_touched [15:58:03] the row doesn't otherwise change [15:58:10] and no revisions are created associated with it [15:58:13] but the value alters [15:58:21] hm, aye [15:58:33] we might get revision text one day, but that would not help us in this case [15:58:37] do you need a when, or do you just need to know if it happens? [15:58:43] we want to have something that lets us know records that have changed [15:58:44] But in Hive we want to have the current row for each page from MySQL wouldn't we? [15:58:53] i suppose if it happens is fine [15:59:07] It page_touched changes, the row changes, so we need to re-sqoop it. [15:59:10] yeah, actually, qchris, that is not something I Have loooked into yet either...how to do incremental updates in hive [15:59:25] probalby hard or not possible, you'd just have to append anyway, and select recent data over old data? [15:59:26] dunno. [15:59:36] that's one reason i'd prefer to deal with appends only at first... [15:59:38] well, if you're using revisionID for revisions, why not use the page table's mirroring of said rev_id? [15:59:45] hmmmMMm [15:59:52] well, nop [15:59:53] no [15:59:55] we don't care about revisions yet [16:00:04] Ironholds: this is to make sure that page data is synced in hive [16:00:09] gotcha [16:00:13] hrm :/ [16:00:14] so, each time sqoop runs, we need to know which recorfds need to be synced [16:00:19] huh. Wait, there's an easier way [16:00:25] so doing something like [16:00:29] are you planning on running this more than once a month? [16:00:33] where updated_at > TIMESTAMP [16:00:33] or [16:00:38] where page_id > PAGE_ID [16:00:43] naw, WHERE page_id IN [16:00:56] Ironholds: depends on how often you think we should.. i was thiking once a week maybe [16:00:56] oh . log! [16:00:58] or more often [16:01:00] ? [16:01:06] ottomata, less than 30 days, doable [16:01:13] ladies and gentlemen, and all those otherwise defined or undefined [16:01:21] allow me to introduce you to the wonders of the recentchanges table :D [16:01:27] Right. [16:01:39] https://www.mediawiki.org/wiki/Manual:Recentchanges_table [16:02:37] reading. [16:02:37] so update so-on-so-forth WHERE page_id IN (SELECT r [16:02:39] so [16:02:39] ack [16:02:54] rc_cur_id FROM recentchanges WHERE rc_timestamp >= foobar [16:02:59] yeah [16:03:01] ok. [16:03:04] * Ironholds jazz hands [16:03:13] errrg, but, hm, still [16:03:18] does that mean the page record got updated? [16:03:23] yep [16:03:25] or, it should [16:03:36] if a change is in recentchanges, it should be mirrored in revision/log/page as appropriate [16:03:41] well, i mean, it will get us a lot of false positives, ja? [16:03:46] why? [16:04:06] a revision change does not mean a page change [16:04:13] it means a change to the pages table [16:04:22] it doe? [16:04:25] it'll increment the value of "what is the most recent revision associated with this page" [16:04:30] and also page_touched [16:04:38] (I forget the field name for the first one) [16:04:43] but the row will change, yes, or should. [16:04:47] hm, ok. [16:04:53] (ah, page_latest) [16:05:12] ah [16:05:13] hm, ok [16:05:21] Oook. [16:05:26] it's gnarly but it works [16:06:05] Rule 7: systems are optimised to fulfill production needs. As an unintended consequence, they are optimised to frustrate analytics needs. [16:08:13] ok, thanks Ironholds, i got some more thinking to do now... :)_ [16:08:17] np! [16:08:30] If there's one thing I know it's where the bodies are buried in mediawiki's db schema. [16:09:54] hey qchris [16:09:59] Hi tnegrin [16:10:19] Eric and I want to take a look at your webstatscollector port -- do you have a link? [16:10:25] ErikZ [16:10:36] For the sql? [16:10:41] Or the output files? [16:10:43] yeah -- the hive script [16:10:50] Sure ... let me find it. [16:10:52] it's part of my secret plan to get Erik using hadoop :) [16:12:02] https://git.wikimedia.org/blob/analytics%2Frefinery.git/37056b31c6a5ae3363647b785d1acee66b09ce58/oozie%2Fwebstats%2Finsert_hourly_pagecounts%2Finsert_hourly_pagecounts.hql [16:12:13] ^ this converts webrequests to pagecounts. [16:12:23] sweet -- thanks! [16:12:23] https://git.wikimedia.org/blob/analytics%2Frefinery.git/37056b31c6a5ae3363647b785d1acee66b09ce58/oozie%2Fwebstats%2Fgenerate_hourly_files%2Fgenerate_hourly_pagecounts_file.hql [16:12:30] ^ this renders the pagecount files [16:12:36] https://git.wikimedia.org/blob/analytics%2Frefinery.git/37056b31c6a5ae3363647b785d1acee66b09ce58/oozie%2Fwebstats%2Fgenerate_hourly_files%2Fgenerate_hourly_projectcounts_file.hql [16:12:42] ^ this renders the projectcount files [16:12:51] oh nice! [16:13:26] And on stat1002 You'll find some rendered file at /mnt/hdfs/wmf/data/archive/webstats/2014/2014-09/ [16:13:42] :) -- nice work qchris [16:13:48] Ironholds: do you have an idea of how many records would change, say, weekly? [16:13:58] ottomata, I can find out [16:14:00] gimme 30s? [16:14:02] k [16:14:03] :) [16:16:09] (running) [16:16:40] Are we sure that each change in a page row causes a recentchanges entry? [16:16:58] it should [16:17:04] wait. hmn. [16:17:05] * Ironholds thinks [16:17:12] okay, it won't necessarily catch page_touched changes [16:17:17] or, not all of them. [16:17:35] ;-) [16:17:41] So it won't catch "templateX, which is called in PageY, updated, so PageY's page_touched updated, so update PageY" [16:17:56] I'm not sure how big of a deal this is. I mean: what do people expect this table will be used for? [16:18:17] yeah, it might not be a big deal at all. but, hm, what if we are trying to do some complicated category pageview thing? [16:18:18] ottomata, 552,381 on enwiki in the last 7 days [16:18:24] i know that is very complicated [16:18:37] hmn. [16:18:38] * Ironholds thinks [16:18:42] that shouldn't be an issue. [16:18:48] but, let's just for this arguement say we wanted it, and we wanted it each report to report on the head of the page table [16:18:49] Meh. That buys us possible undefinitely outdated copies of rows ... is that worth it? [16:18:52] so, wahtever categories a page is curently in [16:19:00] ottomata, okay, let's use that example [16:19:14] meh, i guess tha'ts categorylinks table......which we'd have the same issue with [16:19:17] so, example scenario: you have page_title. You want to get page_id [16:19:33] you use page_id to match cl_from in categorylinks, retrieve cl_to, boom, categories-this-page-is-in [16:19:40] meh, maybe bad example. i want something where we'd need the data in page (or any updated table, really) to be the most recent from mediaiwki [16:19:52] eh. I don't think it's the most recent that matters [16:19:55] it's: what's out of date? [16:20:07] that is, what fields? [16:20:20] i dunno, well, hm [16:20:27] ok, maybe it doesn't matter? that would make things easier for me [16:20:28] So, the only actions which would alter page_touched, but not be caught through recentchanges, to my knowledge, are modifications to substituted/included elements [16:20:34] which should not modify any other field. [16:20:44] if I import the page table, and only incrementally insert NEW records from the tiem of the first import [16:20:49] is that enough? [16:20:55] i would think that data would get stale. [16:20:56] Things like protection or unprotection/state changes to the page, or the insertion of a new revision, or the creation of a new page, should all appear in recentchanges [16:21:19] what about page title changes? [16:21:27] does that makea new page? [16:21:29] that's a move, which is a log action, which appears in recentchanges [16:21:40] it should change page_title but keep page_id. Should. [16:21:41] but, the page_title field is updated on the page table, right? [16:21:47] yep. [16:21:54] aye, this will be kinda weird! [16:21:54] haha [16:21:59] we should log page_id in x-analytics [16:22:02] re insert new records: uhm. I don't understand the question. Not tremendously technical, remember, I just know random stuff. [16:22:08] I would absolutely love if we could do that [16:22:16] * Ironholds drools [16:22:19] that would be the best thing [16:22:22] so we can join webrequest on page_id rather than parsing the uri [16:22:29] yerp. [16:22:36] but, so re the page table, or categorylinks table [16:22:38] hm, don't see why we couldn't do that, especially with: https://gerrit.wikimedia.org/r/#/c/157841/ [16:22:51] the only modifications to the rows, that do not appear in recentchanges, should only modify page_touched, which nobody uses. [16:22:54] ..to my knowledge. [16:23:08] I mean, I can't actually think of a thing us researchmonkeys would use it for. [16:23:22] Because it contains so many classes of "touch", it's unreliable as a source of data about, say, editing frequency or whatnot. [16:24:15] aye [16:24:29] i'm just trying to figure out how to keep an updated table in sync in hive. [16:24:33] yeah [16:24:33] in general, really [16:24:43] if we don't care if it is up to date, then that is much easier for me:) [16:24:43] recentchanges as a start point, for the mediawiki-specific questions, I think [16:24:57] you can also sync categorylinks and revision off recentchanges. and log. [16:25:04] and templatelinks, actually. [16:25:25] everything has a pageID, a revID or a logID, somewhere. [16:25:46] qchris: http://hortonworks.com/blog/four-step-strategy-incremental-updates-hive/ [16:25:50] but, i'm wondering... [16:25:54] if we can just maintain a view [16:26:04] * qchris looks [16:26:18] that process describes basically recreating the main table every time you import [16:26:25] not from mysql, but from data in hive. [16:26:34] we could maintain a view that filters out the duplicate data. [16:26:50] or we could just let researchers deal with duplicate records, and have their queries have to filter out the duplicates [16:26:52] like [16:27:08] uhm [16:27:11] join on page_id where page is most recent :p [16:27:13] except, if the problem is updating [16:27:16] yeah [16:27:21] Mhmmm... not sure I am thrilled by that :-D [16:27:24] hehe [16:27:32] not my preferred option ;p [16:27:36] well, the view would do the same thing, except for that researchers wouldn't have to put it in the query [16:27:40] the view would automatically do that [16:27:48] yeah, which is...more optimal [16:27:58] right, but the extra processingstill has to be done every quer [16:28:00] query [16:28:08] my worry would be how we handle those tables that don't, necessarily, on their own have an indication of which row is most recent [16:28:08] hm, i guess this data really isn't that bigdata big [16:28:15] recreating the main table every import (week?) isn't htat bad [16:28:17] I mean, categorylinks you can probably get away with using the update timestamps, just, but.. [16:28:28] ottomata, err. for page, sure. When we get revision in? [16:28:38] revision is append only, isn't it? [16:28:53] no UPDATE queries, ja/ [16:28:55] (i hope!) [16:28:57] gotcha. er. hmn. [16:29:01] no, you'll need to update [16:29:08] why? you can edit history!? [16:29:11] oversight/revision deletion is stored in rev_deleted [16:29:14] pssh [16:29:27] so annoying [16:29:42] well, this process would be the same then...grr.. [16:29:44] and, enwiki alone, has 736m edits. sooo... [16:29:49] I think it may get into big data domains [16:30:39] ok, i propose we just redesign the mediawiki schemas, sound good? [16:30:40] har har har ahr [16:30:47] so is the UPDATE really that much of a PITA? Do you just have to recreate those entries or something? [16:30:51] I'm totally down for this [16:30:58] Ironholds: the problem is there is no UPDATE or DELETE in hive [16:31:03] only insert [16:31:05] NO DELETE?! [16:31:08] WHO DESIGNED THIS [16:31:10] haha [16:31:15] well, its text files [16:31:19] its not a database [16:31:22] its a mapping of sql onto text files [16:31:45] ahh [16:31:47] hmn. [16:31:48] to update sometthing hive would have to know how to go into a file and make an edit. [16:31:51] okay, can I suggest a plan B? [16:31:58] which gets really complicated, because the files can be in arbitrary format [16:32:00] sure? [16:32:42] wait, no, that wouldn't work [16:32:59] I was thinking you could create a temp table with the new values that followed the same partition scheme, and then join them [16:33:03] but that's basically overwriting [16:33:05] uh, milimetric where can I find this meetup meeting? [16:33:17] i'm in the batcave ottomata [16:33:23] but I'm alone [16:33:29] Ironholds: ya, that link suggests: [16:34:22] 1. import updated data to separate temp table [16:34:22] 2. query the main table and the temp table unioning to get only the latest records [16:34:22] 3. replace main table with query results [16:34:34] (there are some other steps in there), but that's basically it [16:34:51] so, mysql imports areincremental [16:34:58] but the hive table gets totally replaced each time [16:35:01] that's basically what I was thinking [16:35:02] from data in hdfs [16:35:06] yeah, hence the problem. gr. [16:35:18] hmn [16:35:19] So.. We're supposed to be meeting now, right? [16:35:25] Oh. batcave. [16:35:26] I see. [16:35:27] halfak: yeah we're all in batcave [16:35:31] waiting there at least. [16:35:33] what for? [16:35:37] I don't have anything on my calendar [16:35:42] trip planning? [16:35:46] yes Ironholds [16:35:52] sorry guys, just sent the video link [16:35:55] ottomata, we need lzia's prediction models. [16:36:02] if we knew what pages people would edit, we could partition that way [16:36:09] and so just create a new partition and drop the old one [16:36:10] * Ironholds nods firmly [16:36:24] we just need to predict the future perfectly and all these problems go away. [16:36:42] haha [16:37:14] nuria_: you should have the video link [17:01:03] I'm going to hop in the batcave to start filling in ideas. [17:09:28] analytics-logbot: who are you? [17:09:28] I am a logbot running on tools-exec-14. [17:09:28] Messages are logged to www.mediawiki.org/wiki/Analytics/Server_Admin_Log. [17:09:28] To log a message, type !log . [17:09:43] Hahaha :-) [17:09:57] :) [17:27:45] Analytics / Tech community metrics: "Age of unreviewed changesets by affiliation" shows negative number of changesets - https://bugzilla.wikimedia.org/70600#c9 (Quim Gil) Progress! It is strange to find so many Unknown. Any developer with a @wikimedia.org email address is a WMF employee. Any developer... [18:02:48] (PS1) QChris: Add timestamps for missing runs, when selecting them [analytics/refinery] - https://gerrit.wikimedia.org/r/163629 [18:02:55] (PS1) QChris: Order missing runs by hostname and sequence numbers [analytics/refinery] - https://gerrit.wikimedia.org/r/163630 [18:03:02] (PS1) QChris: Drop table_name in usage example for missing sequence numbers [analytics/refinery] - https://gerrit.wikimedia.org/r/163631 [18:04:25] (CR) QChris: Drop table_name in usage example for missing sequence numbers (1 comment) [analytics/refinery] - https://gerrit.wikimedia.org/r/163631 (owner: QChris) [18:30:34] Analytics / Refinery: Raw webrequest partitions for 2014-09-28T04:xx:xx not marked successful - https://bugzilla.wikimedia.org/71425 (christian) NEW p:Unprio s:normal a:None For the hour 2014-08-28T04:xx:xx, none [1] of the the four sources' bucket was marked successful. What happened?... [18:30:49] Analytics / Refinery: Raw webrequest partitions for 2014-09-28T04:xx:xx not marked successful - https://bugzilla.wikimedia.org/71425#c1 (christian) NEW>RESO/FIX Between 04:52:27--04:53:01 (so ~35 seconds) in total ~200K log lines have been dropped. Drop happened across all datacenters, across all... [18:31:02] Analytics / General/Unknown: Kafka broker analytics1021 not receiving messages every now and then - https://bugzilla.wikimedia.org/69667 (christian) [18:36:16] Analytics / Refinery: Make webrequest partition validation handle races between time and sequence numbers - https://bugzilla.wikimedia.org/69615#c8 (christian) Happened again for: 2014-09-28T14:xx:xx/2014-09-28T15:xx:xx (on upload) [19:04:03] ottomata: yesterday, all 4 esams bits caches (cp3019-cp3022) dropped quite some messages between ~18:30 and ~20:00. [19:04:12] It seems the same thing happens again today [19:04:18] http://ganglia.wikimedia.org/latest/graph_all_periods.php?hreg[]=%28amssq|cp%29.%2B&mreg[]=kafka.rdkafka.brokers..%2B\.outbuf_cnt&z=large>ype=line&title=kafka.rdkafka.brokers..%2B\.outbuf_cnt&aggregate=1&r=week [19:04:33] http://ganglia.wikimedia.org/latest/?r=week&cs=&ce=&tab=v&vn=varnishkafka-webrequest&hide-hf=false [19:05:04] Do you have any clue what starts on 18:30 on those machines? [19:08:40] (CR) Ottomata: [C: 2 V: 2] Add timestamps for missing runs, when selecting them [analytics/refinery] - https://gerrit.wikimedia.org/r/163629 (owner: QChris) [19:08:51] kafka_drerr go up during that time. [19:09:59] oo, derr goes up, eh? [19:10:16] how about rtt? [19:11:06] it crashes down [19:11:07] http://ganglia.wikimedia.org/latest/graph.php?r=week&z=xlarge&c=Bits+caches+esams&h=cp3019.esams.wikimedia.org&jr=&js=&v=1&m=kafka.rdkafka.brokers.analytics1012-eqiad-wmnet_9092.12.rtt.cnt&ti=kafka.rdkafka.brokers.analytics1012-eqiad-wmnet%3A9092.12.rtt.cnt [19:11:27] But that might be an artifact ... see [19:11:29] http://ganglia.wikimedia.org/latest/graph.php?r=hour&z=xlarge&c=Bits+caches+esams&h=cp3019.esams.wikimedia.org&jr=&js=&v=1&m=kafka.rdkafka.brokers.analytics1012-eqiad-wmnet_9092.12.rtt.cnt&ti=kafka.rdkafka.brokers.analytics1012-eqiad-wmnet%3A9092.12.rtt.cnt [19:12:06] tnegrin: our 1:1 got canceled today? [19:12:14] it’s not on my calendar any more [19:14:35] whoa, down? [19:14:47] same on cp3022: [19:14:49] http://ganglia.wikimedia.org/latest/graph.php?r=hour&z=xlarge&c=Bits+caches+esams&h=cp3022.esams.wikimedia.org&jr=&js=&v=1&m=kafka.rdkafka.brokers.analytics1012-eqiad-wmnet_9092.12.rtt.cnt&ti=kafka.rdkafka.brokers.analytics1012-eqiad-wmnet%3A9092.12.rtt.cnt [19:15:28] hm, qchris, this is ahppening right now? [19:15:28] Sep 29 19:15:01 cp3019 varnishkafka[8481]: PRODUCE: Failed to produce Kafka message (seq 5299574157): No buffer space available (500000 messages in outq) [19:15:38] Yes. [19:15:45] That's why I pinged you. [19:15:52] It hapened yesterday around this time. [19:15:57] And again right now. [19:16:39] I noticed while looking at yesterdays graphs, that the relevant lines go up again today at the same time. [19:21:34] so, qchris, recently, this happened yesterday at this time [19:21:35] and today [19:21:37] and that is all, rifght? [19:21:41] and just on esams bits? [19:21:44] yes. [19:21:46] yes. [19:22:03] analytics1021 dropped out yesterday 04:00. [19:22:06] yes. [19:22:16] ok, so since this is just bits, it seems unlikely that this is esams -> eqiad networking problems [19:22:27] i haven't seen this kind of problem in a while now though>..>..>.. [19:22:28] hm [19:22:29] yes, [19:22:47] is it possilbe that without all 4 brokers, bits esams can't process the acks fast enough? [19:22:48] hm [19:23:06] maybe only with 3 brokers, during high load time, the 3 can't process acks fast enough, so varnishkafka fills up? [19:23:07] hm [19:23:12] suspcious [19:23:32] maybe there a threshold that they have reached. [19:24:18] I am just walking through the logs, and could not find anything suspicious there (up to now). [19:24:34] yeah [19:24:54] hm, we are doing > 3500 msgs / sec on those [19:29:26] Yesterday, we the highest req/s was also on between 18:00 and 19:00 and decreased afterwards: http://dpaste.com/10MCN4Q [19:29:39] So that would not contract the theory. [19:29:47] s/contract/contradict/ [19:30:34] hmmm, i could see this happening [19:30:39] currently [19:30:40] # The ack timeout of the producer request in milliseconds [19:30:40] kafka.topic.request.timeout.ms = 30000 [19:30:53] that means that a message could be waiting for an ack up to 30 seconds [19:31:22] mhmm. [19:31:28] in a 30 second window, there could queue up to 120000 messages (at 4K / sec, rounding up here) [19:31:41] our buffer size is 500000 msgs [19:31:58] hmmm [19:31:59] hmm [19:32:01] i udnno [19:32:01] hm [19:32:10] Right. The comments above the buffer talk about ~6000 msgs/s [19:32:21] so that shoudl give us 125 seconds of buffer at 4000 / sec [19:32:34] each message can be retried up to 3 times [19:32:44] hm [19:33:39] at 4K / second, with retries=3, with a ack timeout of 30 seconds, there should be no more than 360000 messages in the queue, right? [19:33:56] are we doing the squoop thing or what. [19:34:03] ottomata: yup. [19:41:07] qchris, i'm going to restart vanrihskafka just on cp3019 [19:41:42] k [19:42:01] qchris: at least I know that the varnishkafka logging is working again, i almost wasn't sure [19:42:18] since we weren't seeing logs about dropped messages during the zookeeper timeouts, even though we see lots messages in the hive data [19:42:22] lost* [19:42:24] Hahaha. [19:42:41] so, something is extra fishy there... [20:03:07] qchris: check this out: [20:03:08] http://ganglia.wikimedia.org/latest/graph.php?r=month&z=xlarge&title=&vl=&x=&n=&hreg[]=cp3022&mreg[]=kafka.rdkafka.topics.webrequest_bits.partitions..%2Bmsgq_cnt>ype=stack&glegend=show&aggregate=1 [20:03:33] Whoa :-) [20:04:09] Did bits increase that much, or is that a misleading graph? [20:05:02] these are varishkafka msg queses [20:05:08] so, that just means how many messages are hanging out [20:05:13] on sept 9th, i did [20:05:16] Increase queue_buffering_max_ms again to cover for 10+ second pauses on analytics1021 [20:05:20] If86de9f685198bb52fb46d732a2af032cf6e27ea [20:05:42] seems to match the time when this changed [20:06:08] agreed. [20:08:15] I meanwhile tried to make sense of [20:08:16] http://ganglia.wikimedia.org/latest/graph.php?r=4hr&z=xlarge&hreg[]=%28amssq|cp%29.%2B&mreg[]=kafka.rdkafka.brokers..%2B\.waitresp_cnt>ype=line&title=kafka.rdkafka.brokers..%2B\.waitresp_cnt&aggregate=1 [20:08:18] qchris, and the volumne [20:08:32] i'm not totally sure how xmit_msgq_cnt and msgq_cnt relate to buffer sizes [20:08:40] i would think they both count toward buffer size, but not sure [20:08:40] The brokers only are slow to respond to esam bits. For the others, they are way faster. [20:09:02] only esams bits? [20:09:03] or all esams? [20:09:04] To be honest ... I have no clue what the graph names and config settings mean. [20:09:21] Only esams bits. [20:09:33] that is strange, hm. [20:09:46] For example cp3014 has way lower readings in that graph. [20:11:22] hmmm, the esams bits do more traffic than any other esams varnish [20:11:27] i see uploads at around 1.5-2K [20:13:34] qchris i do not totally know what all these different queues are either [20:13:49] i know that msgq_cnt is the for first queue that that the messages go to from varnishkafka -> rdkafka [20:13:57] I was just about to ask whether you could at some point give me an interduction about them :-) [20:14:09] yeah need more documentation! [20:14:32] And msgq_cnt means how many messages are in that queue? [20:15:13] yes, all of the _cnts mean that [20:15:21] a count of messages of some kind [20:15:27] Ok. [20:15:37] rktp_msgq; /* application->rdkafka queue. [20:15:42] rktp_xmit_msgq; /* internal broker xmit queue */ [20:16:06] hmm, i would guess [20:16:22] that waitresp_cnt woudl be a count of batched produce requests waiting for response [20:16:23] so [20:16:45] Ok. So a higher value need not be bad. [20:18:07] well, to a point, but yeah [20:18:22] i'm trying to understand how my change affected xmit_queue_cnt [20:18:29] or [20:18:31] msgq_cnt [20:19:20] it does look like it amost caused msgq_cnt to increase...but I would think that the kafka.batch.num.messages = 6000 would take precedence over kafka.queue.buffering.max.ms = 30000 [20:19:28] Hey ottomata, I just got done singing your gospel. [20:19:34] https://github.com/edenhill/librdkafka/blob/761ecb859fef4227bf229728a026b9c1f78a4aca/INTRODUCTION.md#performance [20:19:37] hah, oh? [20:19:41] I did a sqoop makeup session with Ironholds and DarTar [20:19:43] the no meetings please lord? [20:19:46] awesooome! [20:19:55] And it all worked :) [20:19:59] so awesooome [20:20:09] were they excited ? :) [20:20:11] Also, we want more things now. [20:20:14] good! [20:20:15] Definitely. [20:20:23] :) [20:20:44] oh, hm [20:20:50] minimum number, not maximum number. [20:21:54] well, anyway, qchris, this is clearly the cause of the problem, and it did not help us avoid lost messages during timeouts [20:22:03] it looks to me like those lost messages are not rdkafka's fault. [20:22:23] ok. [20:23:07] i might even put it back at its default of 1000 [20:23:07] ms [20:23:30] the first time i ever changed that was aug 25 [20:24:03] Sure, we can try 1000 again. [20:24:12] and yeah [20:24:14] qchris: [20:24:15] http://cl.ly/image/3N3i2L04161r [20:24:34] :-) [20:46:20] (PS2) Ottomata: Order missing runs by hostname and sequence numbers [analytics/refinery] - https://gerrit.wikimedia.org/r/163630 (owner: QChris) [20:46:25] (CR) Ottomata: [C: 2 V: 2] Order missing runs by hostname and sequence numbers [analytics/refinery] - https://gerrit.wikimedia.org/r/163630 (owner: QChris) [20:46:44] (PS2) Ottomata: Drop table_name in usage example for missing sequence numbers [analytics/refinery] - https://gerrit.wikimedia.org/r/163631 (owner: QChris) [20:46:48] (CR) Ottomata: [C: 2 V: 2] Drop table_name in usage example for missing sequence numbers [analytics/refinery] - https://gerrit.wikimedia.org/r/163631 (owner: QChris) [20:47:06] Thanks ottomata! [20:47:24] Btw ... kafka docs on queue.buffering.max.ms say [20:47:25] Maximum time to buffer data when using async mode. For example a setting of 100 will try to batch together 100ms of messages to send at once. This will improve throughput but adds message delivery latency due to the buffering. [20:47:29] https://kafka.apache.org/08/configuration.html [20:48:29] If that roughly matches librdkafka, a short value would not be to bad ... would it? [20:48:49] (PS1) Milimetric: Update for October meeting [analytics/reportcard/data] - https://gerrit.wikimedia.org/r/163676 [20:49:01] (CR) Milimetric: [C: 2 V: 2] Update for October meeting [analytics/reportcard/data] - https://gerrit.wikimedia.org/r/163676 (owner: Milimetric) [20:49:30] yeah, that is what librdkafka says too........I increased that while talking to magnus about how to get over possible metadata propogation changes, but that config seems completely irrelevant to that now that we are reading it again [20:49:35] https://github.com/edenhill/librdkafka/blob/master/CONFIGURATION.md [20:49:39] Maximum time, in milliseconds, for buffering data on the producer queue. [20:49:41] same for librdkafka [20:50:22] hmm, librdkafka configs and intro say differen things about [20:50:25] batch.num.messages [20:50:26] https://github.com/edenhill/librdkafka/blob/master/CONFIGURATION.md [20:50:28] https://github.com/edenhill/librdkafka/blob/master/INTRODUCTION.md [20:50:53] :-) [20:51:48] https://github.com/edenhill/librdkafka/issues/151 [20:52:00] qchris, i always thought it was max number [20:52:29] Yes, that's confusing. [20:52:58] but, seeing as the queues got really full when we changed queue.buffering.max.ms [20:53:00] it must be minimum [20:55:22] I guess I only know that I do not know :-/ [20:56:05] hah [20:56:29] But in the kafka docs ... the max somehow makes sense. [20:57:06] So kafka would not wait for longer than queue.buffering.max.ms before trying to send ... would it? [20:57:28] "not wait for longer than" -> Maximum [20:57:34] that's what I thought. [20:57:35] https://github.com/edenhill/librdkafka/issues/151 [20:58:16] I like his response :-) [21:03:16] yeah, that's how I always thought it worked, but if that was so, how did increasing queue.buffering.max.ms increase the msgq_cnt size so much? [21:04:08] Only if batch.num.messages was ridiculously high (which 6000 is not :-) ) ... or is something is wrong. [21:04:35] If batch.num.messages was ignored ... or say 600000000, then it would explain things. [21:04:41] yes, agree [21:18:50] (PS10) Nuria: Bootstrapping from url. Keeping state. [analytics/dashiki] - https://gerrit.wikimedia.org/r/160685 (https://bugzilla.wikimedia.org/70887) [21:33:20] qchris: is this making sense to you? [21:33:20] https://github.com/edenhill/librdkafka/issues/151 [21:33:39] * qchris reads it again [21:33:58] Hahahaha :-) [21:35:08] ok, maybe making sense, calling it minumum or maximum is bad then [21:35:09] to me [21:35:09] ha [21:35:18] why not just say' that's the number of messages in a batch! [21:35:20] I think the wording is not perfect. [21:35:26] Yes, totally! [21:36:08] Well ... actually ... [21:36:32] If the timeout passes before, there might be less messages in a batch. [21:36:42] So the maximum number of messages in a batch. [21:36:47] Just as you said before. [21:37:27] And (assuming the timeout is never reached) the number of messages in a batch! (which is the same as either min or max). [21:37:35] well, then it is a maximum. [21:37:38] there is no minium [21:37:42] 1 message might be send [21:37:43] sent [21:37:46] in a batch [21:37:52] Yes totally. [21:38:12] If the timeout is allowed to be reached, it is a maximum. [21:39:44] (CR) Milimetric: Bootstrapping from url. Keeping state. (2 comments) [analytics/dashiki] - https://gerrit.wikimedia.org/r/160685 (https://bugzilla.wikimedia.org/70887) (owner: Nuria) [21:41:29] btw ... I was reading up on acks ... does [21:41:30] https://git.wikimedia.org/blob/operations%2Fpuppet%2Fvarnishkafka.git/0838c6647c02a3d179a9753dfd172576cbdd63b5/manifests%2Fdefaults.pp#L20 [21:41:41] Explain why we see loss during leader re-election? [21:41:53] Could a "-1" instead fix it? [21:41:59] https://kafka.apache.org/08/configuration.html [21:42:14] ^ says: [21:42:17] 1, which means that the producer gets an acknowledgement after the leader replica has received the data. This option provides better durability as the client waits until the server acknowledges the request as successful (only messages that were written to the now-dead leader but not yet replicated will be lost). [21:42:44] -1, which means that the producer gets an acknowledgement after all in-sync replicas have received the data. This option provides the best durability, we guarantee that no messages will be lost as long as at least one in sync replica remains. [21:43:38] ottomata: ^ [21:51:04] phone hang on... [21:54:12] Just giving it a shot at: https://gerrit.wikimedia.org/r/163744 [22:10:30] Analytics / Refinery: Raw webrequest partitions that were not marked successful - https://bugzilla.wikimedia.org/70085 (christian) [22:10:32] Analytics / Refinery: Duplicates/missing logs from esams bits for 2014-09-28T{18,19,20}:xx:xx - https://bugzilla.wikimedia.org/71435 (christian) NEW p:Unprio s:normal a:None Between, 2014-09-28T18:31:10 and 2014-09-28T20:06:34 all esams bits caches saw both duplicate and missing lines. Loo... [22:13:41] qchris: [22:14:04] yeah, i have been thinking about that too, but it doesn't totally make sense to me [22:14:21] in this case, the broker that timeout ACKs the messages, AND it does not disappear [22:15:15] i would think that the broker would replicate those messages to the others when it comes back online... [22:15:20] back into the ISR [22:15:31] hmmm, but maybe not if the leader changes out from under it? [22:15:37] i asked this question today on the kafka mailin list [22:16:28] ah. ok. [22:16:32] Good to know :-) [22:17:56] qchris, I asked this: [22:18:12] https://gist.github.com/ottomata/3100c31046a428acb9d1 [22:18:35] * qchris looks [22:21:01] Curious what they'll answer. [22:24:18] Gonna call it a day. See you tomorrow! [22:24:22] * qchris waves [22:25:55] ok me too [22:25:57] laaters! [23:05:45] (PS11) Nuria: Bootstrapping from url. Keeping state. [analytics/dashiki] - https://gerrit.wikimedia.org/r/160685 (https://bugzilla.wikimedia.org/70887) [23:08:17] (CR) Nuria: Bootstrapping from url. Keeping state. (2 comments) [analytics/dashiki] - https://gerrit.wikimedia.org/r/160685 (https://bugzilla.wikimedia.org/70887) (owner: Nuria) [23:32:23] halfak: let's have a meeting to clear concerns with: https://gerrit.wikimedia.org/r/#/c/162194/ [23:32:40] Sounds good. [23:32:47] halfak: rather, please let me know if you think it will be time well spent [23:32:50] ah ok [23:33:02] +12 [23:33:04] bah [23:33:07] just +1 [23:33:09] :) [23:33:31] ok