void onTrace(ObjectMap::value_type ov, const qi::EventTrace& trace) { static qi::int64_t secStart = 0; if (!secStart && !full) secStart = trace.timestamp().tv_sec; static unsigned int maxLen = 0; std::string name = boost::lexical_cast<std::string>(trace.slotId()); if (!numeric) { qi::MetaObject mo = ov.second.metaObject(); qi::MetaMethod* m = mo.method(trace.slotId()); if (m) name = m->name(); else { qi::MetaSignal* s = mo.signal(trace.slotId()); if (s) name = s->name(); else name = name + "(??" ")"; // trigraph protect mode on } } if (!full && name.size() > 25) { name = name.substr(0, 22) + "..."; } std::string serviceName = ov.first; if (!full && serviceName.size() > 17) serviceName = serviceName.substr(0, 14) + "..."; maxLen = std::max(maxLen, (unsigned int)name.size()); unsigned int traceKind = trace.kind(); if (traceKind > 4) traceKind = 0; std::string spacing(maxLen + 2 - name.size(), ' '); std::string spacing2((full?maxServiceLength:17) + 2 - ov.first.size(), ' '); if (trace.kind() == qi::EventTrace::Event_Result || qi::EventTrace::Event_Error) { std::cout << serviceName << spacing2 << trace.id() << ' ' << ThreadFormat(trace.callerContext()) << ' ' << ThreadFormat(trace.calleeContext()) << ' ' << callType[traceKind] << ' ' << name << spacing << (trace.timestamp().tv_sec - secStart) << '.' << trace.timestamp().tv_usec << ' ' << trace.userUsTime() << ' ' << trace.systemUsTime() << ' ' << qi::encodeJSON(trace.arguments()) << std::endl; } else { std::cout << serviceName << spacing2 << trace.id() << ' ' << ThreadFormat(trace.callerContext()) << ' ' << ThreadFormat(trace.calleeContext()) << ' ' << callType[traceKind] << ' ' << name << spacing << (trace.timestamp().tv_sec - secStart) << '.' << trace.timestamp().tv_usec << ' ' << qi::encodeJSON(trace.arguments()) << std::endl; } }
// handle a new EventTrace void TraceAnalyzer::addTrace(const qi::EventTrace& trace, unsigned int obj) { qiLogDebug() << "addTrace " << trace.id() << " " << trace.callerContext() << ' ' << trace.calleeContext() << ' ' << trace.kind(); /* a trace-end event without the start available goes in * traceBuffer and that's it. * trace-end event with start available completes the entry * trace-start event gets inserted in the graph, and in the * per-uid perId map, so that future trace-end message can find it quickly */ CallData* d = nullptr; CallList& lc = _p->perContext[trace.calleeContext()]; EventTrace::EventKind k = trace.kind(); if (k == EventTrace::Event_Call || k == EventTrace::Event_Signal) { // New element, insert in toplevel timeline or in trace children // Taking care of stealing async children if they were misplaced d = new CallData(obj, trace); insertTrace(lc, d); // check if we have an async parent if (d->tPost) { // if tPost is set, we have an async parent. // Note that it can be on the same context as us qiLogDebug() << "look for async parent " << trace.callerContext(); CallList& asyncParentCtx = _p->perContext[trace.callerContext()]; insertAsyncParentTrace(asyncParentCtx, d); } TraceBuffer::iterator it = _p->traceBuffer.find(trace.id()); if (it != _p->traceBuffer.end()) { // end already there d->complete(it->second); _p->traceBuffer.erase(it); // ...and go on below } else { _p->perId[d->uid] = d; return; } } else { // Complete the element. d = _p->perId[trace.id()]; if (!d) { // We got the reply before the call, store it _p->traceBuffer[trace.id()] = trace; //qiLogWarning() << "Trace not registered : " << trace.id(); return; } d->complete(trace); _p->perId.erase(trace.id()); } // look for the list that should contain us CallList& container = d->parent?d->parent->children:lc; CallList::iterator it = std::find_if(container.begin(), container.end(), CompUid(trace.id())); if (it == container.end()) { qiLogInfo() << "Message not where it should be"; return; } // now that we know when we stopped, eat-up children // well, that sentence did not came out as I expected CallList::iterator inext = it; ++inext; CallList::iterator iend = inext; while (iend != container.end() && (*iend)->tEnd && (*iend)->tEnd < (*it)->tEnd) ++iend; //CallList::iterator iend = std::upper_bound(inext, container.end(), (*it)->tEnd, CompEndTime()); if (iend != inext) qiLogDebug() << "Splicing at least " << (*inext)->uid << ' ' << (*it)->tEnd << ' ' << (*inext)->tEnd; (*it)->children.splice((*it)->children.begin(), container, inext, iend); for (CallList::iterator ic = (*it)->children.begin(); ic != (*it)->children.end(); ++ic) (*ic)->parent = *it; // and also check if we are child of the element above if ((*it)->tEnd && it != container.begin()) { CallList::iterator prev = it; --prev; if ((*prev)->tEnd && (*prev)->tEnd > (*it)->tEnd) { qiLogDebug() << "Append to prev's children " << (*prev)->tEnd << ' ' << (*it)->tEnd << ' ' << (*prev)->tStart << ' ' << (*it)->tStart; insertTrace((*prev)->children, *it, *prev); container.erase(it); } } }