serial message ack is slow

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.