[Bug 1734788] Re: serial message ack is slow

[Corey Bryant]

** Also affects: python-oslo.messaging (Ubuntu Artful)
   Importance: Undecided
       Status: New

** Changed in: python-oslo.messaging (Ubuntu Artful)
       Status: New => Triaged

** Changed in: python-oslo.messaging (Ubuntu Artful)
   Importance: Undecided => Medium

** Also affects: cloud-archive/pike
   Importance: Undecided
       Status: New

** Changed in: cloud-archive
       Status: New => Fix Released

** Also affects: cloud-archive/ocata
   Importance: Undecided
       Status: New

** Changed in: cloud-archive/ocata
       Status: New => Triaged

** Changed in: cloud-archive/pike
       Status: New => Triaged

** Changed in: cloud-archive/pike
   Importance: Undecided => Medium

** Changed in: cloud-archive/ocata
   Importance: Undecided => Medium

** Changed in: cloud-archive
   Importance: Undecided => Medium

** Changed in: python-oslo.messaging (Ubuntu)
   Importance: Undecided => Medium

-- 
You received this bug notification because you are a member of Ubuntu
OpenStack, which is subscribed to python-oslo.messaging in Ubuntu.
https://bugs.launchpad.net/bugs/1734788

Title:
  serial message ack is slow

Status in Ubuntu Cloud Archive:
  Fix Released
Status in Ubuntu Cloud Archive ocata series:
  Triaged
Status in Ubuntu Cloud Archive pike series:
  Triaged
Status in oslo.messaging:
  Fix Released
Status in python-oslo.messaging package in Ubuntu:
  Fix Released
Status in python-oslo.messaging source package in Artful:
  Triaged

Bug description:
  this confirms sileht's guess: http://eavesdrop.openstack.org/irclogs
  /%23openstack-telemetry/%23openstack-
  telemetry.2017-11-21.log.html#t2017-11-21T14:17:07

  in ceilometer we use a single thread per listener. it seems there is
  significant time spent on ack'ing messages compared to everything
  else. i've made a hacky patch which adds logging[1]:
  http://logs.openstack.org/09/520109/22/check/oslo.messaging-telemetry-
  dsvm-integration-rabbit/4d0cd5b/logs/screen-ceilometer-
  anotification.txt.gz

  example of slow ack'ing can be found here:

  Nov 27 23:23:19.309865 ubuntu-xenial-ovh-gra1-0001082777 ceilometer-agent-notification[16100]: 2017-11-27 23:23:19.309 16681 WARNING oslo_messaging.server [-] WHHHHHHAT(0): 1c152eebf46443dbb75a34e6cb08ad69, 5f93beb9-f0b3-4c9d-99f6-fa26a741d7ae
  Nov 27 23:23:19.321231 ubuntu-xenial-ovh-gra1-0001082777 ceilometer-agent-notification[16100]: 2017-11-27 23:23:19.320 16681 WARNING oslo_messaging.notify.dispatcher [-] OKKKKKKK(f3f9b576-d3c9-11e7-986a-fa163eded301, 0:00:03.035383): 1c152eebf46443dbb75a34e6cb08ad69, 5f93beb9-f0b3-4c9d-99f6-fa26a741d7ae
  Nov 27 23:23:20.892141 ubuntu-xenial-ovh-gra1-0001082777 ceilometer-agent-notification[16100]: 2017-11-27 23:23:20.888 16681 DEBUG ceilometer.publisher.gnocchi [-] 35 measures posted against 35 metrics through 10 resources batch_measures /opt/stack/new/ceilometer/ceilometer/publisher/gnocchi.py:421
  Nov 27 23:23:20.892809 ubuntu-xenial-ovh-gra1-0001082777 ceilometer-agent-notification[16100]: 2017-11-27 23:23:20.888 16681 DEBUG ceilometer.publisher.gnocchi [-] Resource cache hit for update 6c185a83-36b9-46de-83b7-b73673ce57b8 _if_not_cached /opt/stack/new/ceilometer/ceilometer/publisher/gnocchi.py:456
  Nov 27 23:23:20.893475 ubuntu-xenial-ovh-gra1-0001082777 ceilometer-agent-notification[16100]: 2017-11-27 23:23:20.889 16681 WARNING oslo_messaging.notify.dispatcher [-] DOOOOOOOONNNNNEE(f3f9b576-d3c9-11e7-986a-fa163eded301): 1c152eebf46443dbb75a34e6cb08ad69, 5f93beb9-f0b3-4c9d-99f6-fa26a741d7ae
  Nov 27 23:23:24.315239 ubuntu-xenial-ovh-gra1-0001082777 ceilometer-agent-notification[16100]: 2017-11-27 23:23:24.313 16681 WARNING oslo_messaging.server [-] WHHHHHHAT(0): 7af7e903393b48d88e041aad1dce911f, 3d76c968-63b8-40f3-9dcb-7276d4e44688
  Nov 27 23:23:29.319132 ubuntu-xenial-ovh-gra1-0001082777 ceilometer-agent-notification[16100]: 2017-11-27 23:23:29.318 16681 WARNING oslo_messaging.server [-] WHHHHHHAT(1): b882779aadd64a5a95b51b7743bbb19e, 08dcda5d-1241-4f1c-aabe-70a41b47b1fa
  Nov 27 23:23:30.296866 ubuntu-xenial-ovh-gra1-0001082777 ceilometer-agent-notification[16100]: 2017-11-27 23:23:30.296 16681 WARNING oslo_messaging.notify.listener [-] FIIIIIIIIIINALLY: 1c152eebf46443dbb75a34e6cb08ad69, 5f93beb9-f0b3-4c9d-99f6-fa26a741d7ae

  in the above you can see the single process (16681) where "1c152eebf46443dbb75a34e6cb08ad69" is a batch of messages:
  - "WHHHHHHAT" logs when a batch of messages is fetched and queued.
  - "OKKKKKKK" logs when batch is picked up to be processed (by the single listener thread).
  - "DOOOOOOOONNNNNEE" logs when batch is handled by all endpoints (~1.5s)
  - "FIIIIIIIIIINALLY" logs when all messages in batch have been acknowledged (~10s)

  there is no reason for it to take 10s to ack 35 messages in this case
  when it takes ~1.5s to do the real work of processing the messages.

To manage notifications about this bug go to:
https://bugs.launchpad.net/cloud-archive/+bug/1734788/+subscriptions