Page MenuHomePhabricator

Enable new dispatching mechanism on beta
Closed, ResolvedPublic

Description

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.

Event Timeline

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

https://gerrit.wikimedia.org/r/721023

Change 721023 merged by jenkins-bot:

[operations/mediawiki-config@master] Enable new dispatch mechanism on a few beta wikis

https://gerrit.wikimedia.org/r/721023

Mentioned in SAL (#wikimedia-releng) [2021-09-14T17:17:03Z] <Amir1> delete from wb_changes_dispatch where chd_db = 'enwiki'; (T290985)

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.

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: wb

Mentioned in SAL (#wikimedia-releng) [2021-09-15T08:58:38Z] <Amir1> update wb_changes_dispatch set chd_disabled = 1 where chd_site = 'enwiki'; (T290985)

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}

"job_duration":2.5613760948181152

That's milliseconds, right? It would be quite long if it were seconds...

Judging by the timestamps it's two seconds but I wouldn't worry about it too much. Beta cluster is notoriously slow.

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

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?

Yup, it's 34ms. The slowness is obviously coming from beta cluster and its infrastructure

Ladsgroup assigned this task to Michael.