Bug 1002605
Summary: | Trace queue deletion statistics show msgDepth:0 every time | ||||||||||
---|---|---|---|---|---|---|---|---|---|---|---|
Product: | Red Hat Enterprise MRG | Reporter: | Pavel Moravec <pmoravec> | ||||||||
Component: | qpid-cpp | Assignee: | Pavel Moravec <pmoravec> | ||||||||
Status: | CLOSED CURRENTRELEASE | QA Contact: | Michal Toth <mtoth> | ||||||||
Severity: | medium | Docs Contact: | |||||||||
Priority: | medium | ||||||||||
Version: | 2.3 | CC: | esammons, freznice, iboverma, jross, mtoth, pematous, pmoravec, sauchter, smumford | ||||||||
Target Milestone: | 3.2 | Keywords: | Patch, Reopened, TestCaseProvided | ||||||||
Target Release: | --- | ||||||||||
Hardware: | All | ||||||||||
OS: | All | ||||||||||
Whiteboard: | |||||||||||
Fixed In Version: | qpid-cpp-0.32-3 | Doc Type: | Bug Fix | ||||||||
Doc Text: |
It was discovered that the event and log about deleting some provisionable objects (for example, the queue) have zero counters in many statistics, regardless of the truth values. This caused the information in the event and the log to be incorrect. An update in deletion procedures of the objects now ensures the statistic counters provide proper values both in the event and the log.
|
Story Points: | --- | ||||||||
Clone Of: | Environment: | ||||||||||
Last Closed: | 2015-10-13 13:00:55 UTC | Type: | Bug | ||||||||
Regression: | --- | Mount Type: | --- | ||||||||
Documentation: | --- | CRM: | |||||||||
Verified Versions: | Category: | --- | |||||||||
oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||||||
Cloudforms Team: | --- | Target Upstream Version: | |||||||||
Embargoed: | |||||||||||
Attachments: |
|
Description
Pavel Moravec
2013-08-29 14:10:47 UTC
Created attachment 791879 [details]
Patch proposal
Tricky patch:
It temporarily resets mgmtObject for the deleted queue to zero (while keeping the shared_ptr to the object in auxiliary variable), just to suppress updating statistics when cleaning the queue content.
The same can / should be done for other objects (binding, session,..) whose statistics might get wrong during some cleanup work.
One correction to reproducer: as the "Mgmt delete queue" log appears during periodic processing that runs every 10 seconds by default, let add: sleep 10 before the grep command. Created attachment 792201 [details]
Updated patch proposal
This patch also corrects the identical bug but for sessions and clientCredit / unackedMessages statistics.
Reproducer for the session test case:
qpid-send -m 11 -a "myQueue; {create:always}"
qpid-receive -m 100 -a "myQueue; {create:always}" -f
(in another terminal)
qpid-tool
list connection
call <ID_of_qpid-receive-connection> close
and now check result:
grep Tx /tmp/qpidd.log | grep session
should return "unackedMessages:11"
No other management object than queue and session seems to update its statistics during its closure.
The patch is based on qpid 0.22-4 as I don't suppose a backport to 0.18.
The patch in Comment 1 produces the desired effect but has several issues of confusing the statistics by disconnecting a management object from it's actual object. As long as there's no exceptions it will produce the desired effect and succeed. I'd like to suggest a more direct method. Please refer to generated code in qpid/cpp/managementgen/qmfgen/templates/Class.cpp. In the destructor of the management object is where the trace log is emitted. We could add another method, debugStats(), that would be the exact same code as the Mgmt delete Statistics except that it would take a string and emit a debug log. Then in Queue::destroyed() you could have the addition of two lines if (mgmtObject != 0) mgmtObject->debugStats("Queue destroyed"); to get the stats you want without messing with the mgmtObject pointer. The debug stats code would be autogenerated for every qmf object present and future. The debugStats() function would be available to be called randomly throughout the code base for convenient debugging. Created attachment 793071 [details] patch with debugStats (In reply to Chuck Rolke from comment #4) > The patch in Comment 1 produces the desired effect but has several issues of > confusing the statistics by disconnecting a management object from it's > actual object. As long as there's no exceptions it will produce the desired > effect and succeed. > > I'd like to suggest a more direct method. Please refer to generated code in > qpid/cpp/managementgen/qmfgen/templates/Class.cpp. In the destructor of the > management object is where the trace log is emitted. We could add another > method, debugStats(), that would be the exact same code as the Mgmt delete > Statistics except that it would take a string and emit a debug log. > > Then in Queue::destroyed() you could have the addition of two lines > > if (mgmtObject != 0) > mgmtObject->debugStats("Queue destroyed"); > > to get the stats you want without messing with the mgmtObject pointer. > > The debug stats code would be autogenerated for every qmf object present and > future. The debugStats() function would be available to be called randomly > throughout the code base for convenient debugging. This enhancement makes sense, though having the drawback in explicitly calling debugStats at the beginning of destructor/closing method of every manageable object. As generic Class.cpp destructor can't call debugStats method since queue and session stats are already wrong ("over-updated"). Also, as different exchange types might "over-update" statistics in future, I decided to call the debugStats() method from individual destructors of all exchange types and not from QPID_BROKER_INLINE_EXTERN virtual qpid::broker::Exchange::~Exchange(); Attached is a patch for that. It lacks calling debugStats for memory, as the class qpid::sys::posix::MemStat does not have management object declared, just provided in method argument. Anyway, there is imho no need to fix this as memory statistics are empty now (check current trace "Mgmt delete memory. id:amqp-broker Statistics: {}"). Committed to upstream as r1520579. Tested on qpid-cpp-server-0.30-7 @ rhel6 32/64 and rhel7. Looked mainly on following items: acquires, msgDepth, msgTotal{En,De}queues, msgPersist{En,De}queues, bytePersist{En,De}queues, byteTotal{En,De}queues Marking as verified, as expected values are shown in trace log, when Mgmt queue delete occurs. Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://rhn.redhat.com/errata/RHEA-2015-0805.html Reopenning as it does _not_ work: reproducer fairly simple: echo "trace=yes" >> /etc/qpid/qpidd.conf echo "log-to-file=/tmp/qpidd.log" >> /etc/qpid/qpidd.conf service qpidd restart qpid-config add queue testQueue1 qpid-send --address "testQueue1; {node: { type: queue }, assert: never, create: never}" -m 13 --content-size=1024 qpid-config del queue testQueue1 --force grep testQueue1 /tmp/qpidd.log | grep "destroying queue" Output: 2015-04-30 10:43:25 [Model] trace Mgmt destroying queue. id:testQueue1 Statistics: {acquires:0, bindingCount:0, bindingCountHigh:1, bindingCountLow:0, byteDepth:0, byteFtdDepth:0, byteFtdDequeues:0, byteFtdEnqueues:0, bytePersistDequeues:0, bytePersistEnqueues:0, byteTotalDequeues:14183, byteTotalEnqueues:14183, byteTxnDequeues:0, byteTxnEnqueues:0, consumerCount:0, consumerCountHigh:0, consumerCountLow:0, creator:anonymous, discardsLvq:0, discardsOverflow:0, discardsPurge:0, discardsRing:0, discardsSubscriber:0, discardsTtl:0, flowStopped:False, flowStoppedCount:0, messageLatencyAvg:0, messageLatencyCount:0, messageLatencyMax:0, messageLatencyMin:0, msgDepth:0, msgFtdDepth:0, msgFtdDequeues:0, msgFtdEnqueues:0, msgPersistDequeues:0, msgPersistEnqueues:0, msgTotalDequeues:13, msgTotalEnqueues:13, msgTxnDequeues:0, msgTxnEnqueues:0, redirectPeer:, redirectSource:False, releases:0, reroutes:0, unackedMessages:0, unackedMessagesHigh:0, unackedMessagesLow:0} See byteDepth:0, msgDepth:0. Also msgTotalDequeues should be zero as no dequeue had been made prior deleting the queue. It still sounds the queue first purges its messages and then calls debugSnapshot - something had to changed since the time of my upstream commit. Reproducible on qpid-cpp-server-0.30-8.el6.x86_64 and today's upstream trunk. Fixed by commit https://svn.apache.org/r1676982 . Resetting release flags. How to test: (let print the queue deletion trace twice: first for queue deleted by user, second by shutting-down broker; both results should be the same wrt. the printed log) qpid-config add queue testQueue1 qpid-send --address testQueue1 -m 13 --content-size=1024 qpid-config del queue testQueue1 --force qpid-config add queue testQueue1 qpid-send --address testQueue1 -m 13 --content-size=1024 service qpidd stop grep "destroying queue. id:testQueue1 Statistics:" should return twice the same stats with counters: bindingCount:1, byteDepth:14183, byteTotalDequeues:0, byteTotalEnqueues:14183, msgDepth:13, msgTotalDequeues:0, msgTotalEnqueues:13, Verified on both rhel 6 archs and rhel 7. qpid-cpp-server-0.34-1 msg*Dequeues are correctly showing 0 after queue deletion and not purged number of messages as previously. Thank you Pavel for checking and reopening this BZ. |