The new dispatch mechanism developed in T290368 should now be enabled on a first beta wiki, so that we can test it and come up with sensible metrics and other observability considerations.
Description
Description
Details
Details
| Subject | Repo | Branch | Lines +/- | |
|---|---|---|---|---|
| Enable new dispatch mechanism on a few beta wikis | operations/mediawiki-config | master | +16 -0 |
| Status | Subtype | Assigned | Task | ||
|---|---|---|---|---|---|
| Invalid | None | T108944 [Epic] Improve change dispatching | |||
| Resolved | • jcrespo | T118162 Wikibase dispatchChanges.php runs slow, creates an absurd amount of database connections | |||
| Resolved | karapayneWMDE | T265198 Don’t require extra cronjobs / maintenance scripts for Wikibase | |||
| Resolved | karapayneWMDE | T48643 [Story] Dispatching via job queue (instead of cron script) | |||
| Resolved | Michael | T290985 Enable new dispatching mechanism on beta |
Event Timeline
Comment Actions
Change 721023 had a related patch set uploaded (by Michael Große; author: Michael Große):
[operations/mediawiki-config@master] Enable new dispatch mechanism on a few beta wikis
Comment Actions
Change 721023 merged by jenkins-bot:
[operations/mediawiki-config@master] Enable new dispatch mechanism on a few beta wikis
Comment Actions
Mentioned in SAL (#wikimedia-releng) [2021-09-14T17:17:03Z] <Amir1> delete from wb_changes_dispatch where chd_db = 'enwiki'; (T290985)
Comment Actions
The main job is being triggered:
ladsgroup@deployment-mwlog01:/srv/mw-log$ grep -i DispatchChanges *.log api.log:2021-09-14 17:17:33 [YUDZLXMZR06lCsGM43FiXgAAAAE] deployment-mediawiki11 metawiki 1.38.0-alpha api INFO: API GET 172.16.0.55 172.16.0.55 T=2ms action=streamconfigs format=json streams=mediawiki.job.DispatchChanges constraints=destination_event_service%3Deventgate-main all_settings= EventBus.log:2021-09-14 17:17:33 [YUDZKXMZR06lCsGM43FiVwAAABE] deployment-mediawiki11 wikidatawiki 1.38.0-alpha EventBus DEBUG: Using destination_event_service eventgate-main for stream mediawiki.job.DispatchChanges.
Comment Actions
I do see RC is being injected through our jobs but I can't find the EntityChangeNotification job
*************************** 2. row ***************************
rc_id: 868777
rc_timestamp: 20210914170926
rc_actor: 1745
rc_namespace: 0
rc_title: Foo_Prefix_Test
rc_comment_id: 99791
rc_minor: 1
rc_bot: 0
rc_new: 0
rc_cur_id: 11480
rc_this_oldid: 506943
rc_last_oldid: 506943
rc_type: 5
rc_patrolled: 2
rc_ip:
rc_old_len: 35
rc_new_len: 35
rc_deleted: 0
rc_logid: 0
rc_log_type: NULL
rc_log_action:
rc_params: a:1:{s:20:"wikibase-repo-change";a:14:{s:2:"id";i:1781109;s:4:"time";s:14:"20210914170926";s:7:"user_id";s:3:"548";s:11:"revision_id";s:7:"1262637";s:9:"object_id";s:7:"Q455981";s:4:"type";s:20:"wikibase-item~update";s:11:"entity_type";s:4:"item";s:7:"page_id";i:669975;s:6:"rev_id";i:1262637;s:9:"parent_id";i:1262636;s:7:"comment";s:59:"/* wbsetclaim-update:2||1 */ [[Property:P694]]: [[Q467044]]";s:9:"user_text";s:9:"Ladsgroup";s:15:"central_user_id";i:5217;s:3:"bot";i:0;}}
rc_source: wb
*************************** 3. row ***************************
rc_id: 868778
rc_timestamp: 20210914171732
rc_actor: 1745
rc_namespace: 0
rc_title: Foo_Prefix_Test
rc_comment_id: 99792
rc_minor: 1
rc_bot: 0
rc_new: 0
rc_cur_id: 11480
rc_this_oldid: 506943
rc_last_oldid: 506943
rc_type: 5
rc_patrolled: 2
rc_ip:
rc_old_len: 35
rc_new_len: 35
rc_deleted: 0
rc_logid: 0
rc_log_type: NULL
rc_log_action:
rc_params: a:1:{s:20:"wikibase-repo-change";a:14:{s:2:"id";N;s:9:"object_id";s:7:"Q455981";s:4:"type";s:20:"wikibase-item~update";s:11:"revision_id";s:7:"1262638";s:7:"user_id";s:3:"548";s:4:"time";s:14:"20210914171732";s:11:"entity_type";s:4:"item";s:7:"page_id";i:669975;s:6:"rev_id";i:1262638;s:9:"parent_id";i:1262635;s:7:"comment";s:59:"/* wbsetclaim-update:2||1 */ [[Property:P694]]: [[Q536583]]";s:9:"user_text";s:9:"Ladsgroup";s:15:"central_user_id";i:5217;s:3:"bot";b:0;}}
rc_source: wbComment Actions
Mentioned in SAL (#wikimedia-releng) [2021-09-15T08:58:38Z] <Amir1> update wb_changes_dispatch set chd_disabled = 1 where chd_site = 'enwiki'; (T290985)
Comment Actions
JobExecutor.log:2021-09-15 09:33:15 [YUG91yt4sN@JcQsi-kpvuAAAAAo] deployment-jobrunner04 wikidatawiki 1.38.0-alpha JobExecutor DEBUG: Beginning job execution {"job":"DispatchChanges Special: title=Q455981 entityId=Q455981 requestId=YUG91yt4sN@JcQsi-kpvuAAAAAo","job_type":"DispatchChanges"}
JobExecutor.log:2021-09-15 09:33:18 [YUG91yt4sN@JcQsi-kpvuAAAAAo] deployment-jobrunner04 wikidatawiki 1.38.0-alpha JobExecutor INFO: Finished job execution {"job":"DispatchChanges Special: title=Q455981 entityId=Q455981 requestId=YUG91yt4sN@JcQsi-kpvuAAAAAo","job_type":"DispatchChanges","job_status":true,"job_duration":2.5613760948181152}Comment Actions
Judging by the timestamps it's two seconds but I wouldn't worry about it too much. Beta cluster is notoriously slow.
Comment Actions
It seems to be working:
JobExecutor.log:2021-09-15 10:10:08 [YUHE2Ct4sN@JcQsi-kp2XQAAAAs] deployment-jobrunner04 enwiki 1.38.0-alpha JobExecutor INFO: Finished job execution {"job":"EntityChangeNotification Special: changes=[\"array(...)\",\"array(...)\",\"array(...)\",\"array(...)\",\"array(...)\",\"array(...)\",\"array(...)\"] requestId=YUHE2Ct4sN@JcQsi-kp2XQAAAAs","job_type":"EntityChangeNotification","job_status":true,"job_duration":0.2548799514770508}Just sloooow
Comment Actions
Mh, though this might include multiple changes 🤔
For comparison, the job with a single change on my local dev device:
2021-09-15 10:34:45 EntityChangeNotification Special: changes=["array(...)"] namespace=-1 title= requestId=66b9c75fa5879836461f32d8 (id=12,timestamp=20210915103411) STARTING 2021-09-15 10:34:45 EntityChangeNotification Special: changes=["array(...)"] namespace=-1 title= requestId=66b9c75fa5879836461f32d8 (id=12,timestamp=20210915103411) t=34 good
These are 34ms, right?
Comment Actions
Yup, it's 34ms. The slowness is obviously coming from beta cluster and its infrastructure