plugins/janadot/JEventProcessorJANADOT.cc

0001 // Author: David Lawrence  August 8, 2007
0002 //
0003 //
0004
0005 #include <math.h>
0006
0007 #include <iostream>
0008 #include <iomanip>
0009 #include <fstream>
0010 #include <regex>
0011 #include <set>
0012 using namespace std;
0013
0014 #include <JANA/JApplication.h>
0015 #include "JEventProcessorJANADOT.h"
0016
0017
0018 // Routine used to allow us to register our JEventSourceGenerator
0019 extern "C"{
0020 void InitPlugin(JApplication *app){
0021     InitJANAPlugin(app);
0022     app->Add(new JEventProcessorJANADOT());
0023     app->GetJParameterManager()->SetParameter("RECORD_CALL_STACK", true);
0024 }
0025 } // "C"
0026
0027 //------------------------------------------------------------------
0028 // Constructor
0029 //------------------------------------------------------------------
0030 JEventProcessorJANADOT::JEventProcessorJANADOT() {
0031     SetTypeName("JEventProcessorJANADOT");
0032 }
0033
0034 //------------------------------------------------------------------
0035 // init
0036 //------------------------------------------------------------------
0037 void JEventProcessorJANADOT::Init() {
0038
0039     auto app = GetApplication();
0040     app->SetDefaultParameter("janadot:output_file", m_output_filename, "Output filename for call graph visualization");
0041     app->SetDefaultParameter("janadot:weight_edges", m_weight_edges, "Use edge weight (penwidth) to represent the percent of time spent in call");
0042
0043     // Turn on call stack recording
0044     force_all_factories_active = false;
0045     suppress_unused_factories = true;
0046     focus_factory = "";
0047     try{
0048         app->GetJParameterManager()->SetDefaultParameter("JANADOT:FORCE_ALL_FACTORIES_ACTIVE", force_all_factories_active);
0049         app->GetJParameterManager()->SetDefaultParameter("JANADOT:FOCUS", focus_factory, "Factory to have janadot call graph focus on when drawing.");
0050         has_focus = !focus_factory.empty();
0051         if( has_focus )jout<<" Setting JANADOT focus to: "<< focus_factory <<endl;
0052         app->GetJParameterManager()->SetDefaultParameter("JANADOT:SUPPRESS_UNUSED_FACTORIES", suppress_unused_factories, "If true, then do not list factories in groups that did not show up in list of factories recorded during processing. If false, these will show up as white ovals with no connections (ghosts)");
0053
0054         // User can specify grouping using configuration parameters starting with
0055         // "JANADOT:GROUP:". The remainder of the parameter name is used to name
0056         // the group and the value is a comma separated list of classes to add to
0057         // the group.
0058         map<string,string> parms;
0059         app->GetJParameterManager()->FilterParameters(parms, "JANADOT:GROUP:");
0060         jout<<"JANADOT groups: "<<parms.size()<<endl;
0061         for(map<string,string>::iterator it=parms.begin(); it!=parms.end(); it++){
0062
0063             string group_name = it->first;
0064             jout<<" JANADOT group \""<<group_name<<"\" found ";
0065
0066             // Split vals at commas
0067             vector<string> myclasses;
0068             string str = it->second;
0069             unsigned int cutAt;
0070             while( (cutAt = str.find(",")) != (unsigned int)str.npos ){
0071                 if(cutAt > 0){
0072                     string val = str.substr(0,cutAt);
0073
0074                     // Check if a color was specified
0075                     if(val.find("color_")==0){
0076                         group_colors[group_name] = val.substr(6);
0077                     }else if(val.find("no_box")==0){
0078                         no_subgraph_groups.insert(group_name);
0079                     }else{
0080                         myclasses.push_back(val);
0081                     }
0082                 }
0083                 str = str.substr(cutAt+1);
0084             }
0085             if(str.length() > 0)myclasses.push_back(str);
0086             if(myclasses.size() > 0) groups[it->first] = myclasses;
0087
0088             if(group_colors.find(it->first)!=group_colors.end()){
0089                 jout<<" ("<<group_colors[it->first]<<") ";
0090             }
0091             jout << myclasses.size() << " classes" << endl;
0092         }
0093
0094         // Make an inverted list keyed by node name that has the group color as the value
0095         map<string,vector<string> >::iterator it = groups.begin();
0096         for(; it!=groups.end(); it++){
0097             if(group_colors.find(it->first) == group_colors.end()) continue;
0098             string color = group_colors[it->first];
0099             vector<string> &classes = it->second;
0100             for(unsigned int i=0; i<classes.size(); i++) node_colors[classes[i]] = color;
0101         }
0102
0103     }catch(...){}
0104 }
0105
0106 //------------------------------------------------------------------
0107 // BeginRun
0108 //------------------------------------------------------------------
0109 void JEventProcessorJANADOT::BeginRun(const std::shared_ptr<const JEvent>& /*event*/)
0110 {
0111     // Nothing to do here
0112 }
0113
0114 //------------------------------------------------------------------
0115 // Process
0116 //------------------------------------------------------------------
0117 void JEventProcessorJANADOT::Process(const std::shared_ptr<const JEvent>& event)
0118 {
0119     // If we are supposed to activate all factories, do that now
0120     if(force_all_factories_active){
0121         vector<JFactory*> factories = event->GetAllFactories();
0122         for(unsigned int i=0; i<factories.size(); i++)factories[i]->Create(event);
0123     }
0124
0125     // Get the call stack for ths event and add the results to our stats
0126     auto stack = event->GetJCallGraphRecorder()->GetCallGraph();
0127
0128     // Lock mutex in case we are running with multiple threads
0129     std::lock_guard<std::mutex> lck(mutex);
0130
0131     // Loop over the call stack elements and add in the values
0132     for(unsigned int i=0; i<stack.size(); i++){
0133
0134         // Keep track of total time each factory spent waiting and being waited on
0135         string nametag1 = MakeNametag(stack[i].caller_name, stack[i].caller_tag);
0136         string nametag2 = MakeNametag(stack[i].callee_name, stack[i].callee_tag);
0137
0138         FactoryCallStats &fcallstats1 = factory_stats[nametag1];
0139         FactoryCallStats &fcallstats2 = factory_stats[nametag2];
0140
0141         auto delta_t_ms = std::chrono::duration_cast<std::chrono::milliseconds>(stack[i].end_time - stack[i].start_time).count();
0142         fcallstats1.time_waiting += delta_t_ms;
0143         fcallstats2.time_waited_on += delta_t_ms;
0144
0145         // Get pointer to CallStats object representing this calling pair
0146         CallLink link;
0147         link.caller_name = stack[i].caller_name;
0148         link.caller_tag  = stack[i].caller_tag;
0149         link.callee_name = stack[i].callee_name;
0150         link.callee_tag  = stack[i].callee_tag;
0151         CallStats &stats = call_links[link]; // get pointer to stats object or create if it doesn't exist
0152
0153         switch(stack[i].data_source){
0154             case JCallGraphRecorder::DATA_NOT_AVAILABLE:
0155                 stats.Ndata_not_available++;
0156                 stats.data_not_available_ms += delta_t_ms;
0157                 break;
0158             case JCallGraphRecorder::DATA_FROM_CACHE:
0159                 fcallstats2.Nfrom_cache++;
0160                 stats.Nfrom_cache++;
0161                 stats.from_cache_ms += delta_t_ms;
0162                 break;
0163             case JCallGraphRecorder::DATA_FROM_SOURCE:
0164                 fcallstats2.Nfrom_source++;
0165                 stats.Nfrom_source++;
0166                 stats.from_source_ms += delta_t_ms;
0167                 break;
0168             case JCallGraphRecorder::DATA_FROM_FACTORY:
0169                 fcallstats2.Nfrom_factory++;
0170                 stats.Nfrom_factory++;
0171                 stats.from_factory_ms += delta_t_ms;
0172                 break;
0173         }
0174
0175     }
0176 }
0177
0178 //------------------------------------------------------------------
0179 // fini
0180 //------------------------------------------------------------------
0181 void JEventProcessorJANADOT::Finish()
0182 {
0183
0184     // In order to get the total time we have to first get a list of
0185     // the event processors (i.e. top-level callers). We can tell
0186     // this just by looking for callers that never show up as callees
0187     set<string> callers;
0188     set<string> callees;
0189     map<CallLink, CallStats>::iterator iter;
0190     for(iter=call_links.begin(); iter!=call_links.end(); iter++){
0191         const CallLink &link = iter->first;
0192         string caller = MakeNametag(link.caller_name, link.caller_tag);
0193         string callee = MakeNametag(link.callee_name, link.callee_tag);
0194         callers.insert(caller);
0195         callees.insert(callee);
0196     }
0197
0198     // Loop over list a second time so we can get the total ticks for
0199     // the process in order to add the percentage to the label below
0200     double total_ms = 0.0;
0201     for(iter=call_links.begin(); iter!=call_links.end(); iter++){
0202         const CallLink &link = iter->first;
0203         CallStats &stats = iter->second;
0204         string caller = MakeNametag(link.caller_name, link.caller_tag);
0205         string callee = MakeNametag(link.callee_name, link.callee_tag);
0206
0207         if(callees.find(caller) == callees.end()){
0208             total_ms += stats.from_factory_ms + stats.from_source_ms + stats.from_cache_ms + stats.data_not_available_ms;
0209         }
0210     }
0211     if(total_ms == 0.0)total_ms = 1.0;
0212
0213     // If the user specified a focus factory, find the decendents and ancestors
0214     set<string> focus_relatives;
0215     if(has_focus){
0216         FindDecendents(focus_factory, focus_relatives);
0217         FindAncestors(focus_factory, focus_relatives);
0218     }
0219
0220     // Open dot file for writing
0221     cout<<"Opening output file \"" << m_output_filename << "\""<<endl;
0222     ofstream file(m_output_filename);
0223
0224     file<<"digraph G {"<<endl;
0225
0226     // Loop over call links
0227     for(iter=call_links.begin(); iter!=call_links.end(); iter++){
0228         const CallLink &link = iter->first;
0229         CallStats &stats = iter->second;
0230
0231         unsigned int Ntotal = stats.Nfrom_cache + stats.Nfrom_source + stats.Nfrom_factory;
0232         string nametag1 = MakeNametag(link.caller_name, link.caller_tag);
0233         string nametag2 = MakeNametag(link.callee_name, link.callee_tag);
0234
0235         // Don't draw links when the caller is flagged to be ignored via the special name "<ignore>"
0236         if(nametag1 == "<ignore>") continue;
0237
0238         double my_ms = stats.from_factory_ms + stats.from_source_ms + stats.from_cache_ms;
0239         double percent = 100.0*my_ms/total_ms;
0240         char percentstr[32];
0241         snprintf(percentstr, 32, "%5.1f%%", percent);
0242
0243         string timestr=MakeTimeString(stats.from_factory_ms);
0244
0245         // If a focus factory was specified, check if either the
0246         if(has_focus){
0247             if(focus_relatives.find(nametag1)==focus_relatives.end()) continue;
0248             if(focus_relatives.find(nametag2)==focus_relatives.end()) continue;
0249         }
0250
0251         file<<"\t";
0252         file<<"\""<<nametag1<<"\"";
0253         file<<" -> ";
0254         file<<"\""<<nametag2<<"\"";
0255         file<<" [style=bold, fontsize=8";
0256         file<<", label=\""<<Ntotal<<" calls\\n"<<timestr<<"\\n"<<percentstr<<"\"";
0257         if (m_weight_edges) {
0258             int width = (percent / 20.0) + 1; // width ranges from 1 to 6 points
0259             file<<", penwidth="<<width;
0260         }
0261         file<<"];";
0262         file<<endl;
0263     }
0264
0265     file<<endl;
0266
0267     // Add commands for node drawing style
0268     vector<string> source_nodes;
0269     vector<string> processor_nodes;
0270     set<string> factory_nodes;
0271     map<string, FactoryCallStats>::iterator fiter;
0272     for(fiter=factory_stats.begin(); fiter!=factory_stats.end(); fiter++){
0273         FactoryCallStats &fcall_stats = fiter->second;
0274         string nodename = fiter->first;
0275
0276         // If nodename has special value "<ignore>" then do not draw it. This
0277         // is used by event sources that want to draw the low level objects that
0278         // were made, even though they weren't specifically requested. The
0279         // caller name would then be set to this value and the tag an empty string.
0280         if(nodename == "<ignore>") continue;
0281
0282         // If a focus was specified then check if this node is a relative or not
0283         if(has_focus){
0284             if(focus_relatives.find(nodename)==focus_relatives.end()) continue;
0285         }
0286
0287         // Decide whether this is a factory, processor, or source.
0288         // Because sources can Insert objects that trigger automatic
0289         // factory creation to hold them, the values of call_stats.Nfrom_factory
0290         // and call_stats.Nfrom_cache etc. can be unreliable. Here, we
0291         // rely on whether the node shows up in callers, callees, or both
0292         // to determine the type.
0293         bool is_caller = callers.count(nodename);
0294         bool is_callee = callees.count(nodename);
0295         fcall_stats.type = kFactory; // default
0296         if( (fcall_stats.Nfrom_cache+fcall_stats.Nfrom_factory)>0 && !is_caller ) fcall_stats.type = kCache;
0297         if( fcall_stats.Nfrom_source ) fcall_stats.type = kSource;
0298         if(  is_caller && !is_callee ) fcall_stats.type = kProcessor;
0299
0300         // Get time spent in this factory proper
0301         double time_spent_in_factory = fcall_stats.time_waited_on - fcall_stats.time_waiting;
0302         string timestr=MakeTimeString(time_spent_in_factory);
0303
0304         double percent = 100.0*time_spent_in_factory/total_ms;
0305         char percentstr[32];
0306         snprintf(percentstr, 32, "%5.1f%%", percent);
0307
0308         string fillcolor;
0309         string shape;
0310         switch(fcall_stats.type){
0311             case kProcessor:
0312                 fillcolor = "aquamarine";
0313                 shape = "ellipse";
0314                 if(nodename == "AutoActivated"){
0315                     fillcolor = "lightgrey";
0316                     shape = "hexagon";
0317                 }
0318                 processor_nodes.push_back(fiter->first);
0319                 break;
0320             case kFactory:
0321                 fillcolor = "lightblue";
0322                 if(node_colors.find(nodename)!=node_colors.end()) fillcolor = node_colors[nodename];
0323                 shape = "box";
0324                 if(has_focus && nodename==focus_factory) shape = "tripleoctagon";
0325                 factory_nodes.insert(nodename);
0326                 break;
0327             case kCache:
0328                 fillcolor = "yellow";
0329                 if(node_colors.find(nodename)!=node_colors.end()) fillcolor = node_colors[nodename];
0330                 shape = "box";
0331                 if(has_focus && nodename==focus_factory) shape = "tripleoctagon";
0332                 break;
0333             case kSource:
0334                 fillcolor = "green";
0335                 shape = "trapezium";
0336                 source_nodes.push_back(nodename);
0337                 break;
0338             case kDefault:
0339             default:
0340                 fillcolor = "lightgrey";
0341                 shape = "hexagon";
0342                 break;
0343         }
0344
0345         stringstream label_html;
0346         label_html<<"<TABLE border=\"0\" cellspacing=\"0\" cellpadding=\"0\" cellborder=\"0\">";
0347         label_html<<"<TR><TD>"<<nodename<<"</TD></TR>";
0348         if(fcall_stats.type!=kProcessor){
0349             label_html<<"<TR><TD><font point-size=\"8\">"<<timestr<<" ("<<percentstr<<")</font></TD></TR>";
0350         }
0351         label_html<<"</TABLE>";
0352
0353         file<<"\t\""<<nodename<<"\"";
0354         file<<" [shape="<<shape<<",style=filled,fillcolor="<<fillcolor;
0355         file<<", label=<"<<label_html.str()<<">";
0356         if(fcall_stats.type==kSource)file<<", margin=0";
0357         file<<"];"<<endl;
0358     }
0359
0360     // Make node to specify time
0361     time_t now = time(NULL);
0362     string datetime(ctime(&now));
0363     datetime.erase(datetime.length()-1);
0364     stringstream label_html;
0365     label_html << "<font point-size=\"10\">";
0366     label_html << "Created: "<<datetime;
0367     label_html << "</font>";
0368     file<<"\t\"CreationTime\"";
0369     file<<" [shape=box,style=filled,color=white";
0370     file<<", label=<"<<label_html.str()<<">";
0371     file<<", margin=0";
0372     file<<"];"<<endl;
0373
0374
0375     // Make all processor nodes appear at top of graph
0376     file<<"\t{rank=source; ";
0377     file << "\"CreationTime\";";
0378     for(unsigned int i=0; i<processor_nodes.size(); i++)file<<"\""<<processor_nodes[i]<<"\"; ";
0379     file<<"}"<<endl;
0380
0381     // Make all source nodes appear on bottom of graph
0382     file<<"\t{rank=sink; ";
0383     for(unsigned int i=0; i<source_nodes.size(); i++)file<<"\""<<source_nodes[i]<<"\"; ";
0384     file<<"}"<<endl;
0385
0386     // Add all groups as subgraphs
0387     int icluster=0;
0388     map<string,vector<string> >::iterator it=groups.begin();
0389     for(; it!=groups.end(); it++, icluster++){
0390         string group_name = it->first;
0391         if(no_subgraph_groups.find(group_name) != no_subgraph_groups.end()) continue;
0392
0393         file << "subgraph cluster_" << icluster <<" {";
0394         vector<string> &myclasses = it->second;
0395         for(unsigned int i=0; i<myclasses.size(); i++){
0396             bool include_class = true;
0397             if(suppress_unused_factories){
0398                 include_class = (factory_nodes.find(myclasses[i]) != factory_nodes.end());
0399             }
0400             if(include_class){
0401                 file << "\"" << myclasses[i] << "\"; ";
0402             }
0403         }
0404         file << "label=\"" << group_name << "\"; ";
0405
0406         string color = "forestgreen"; // default box color
0407         //if(group_colors.find(group_name)!=group_colors.end()) color = group_colors[group_name];
0408         file << "color="<<color<<"}" << endl;
0409     }
0410
0411     // Close file
0412     file<<"}"<<endl;
0413     file.close();
0414
0415     // Print message to tell user how to use the dot file
0416     cout<<endl
0417     <<"Factory calling information written to \"jana.dot\". To create a graphic"<<endl
0418     <<"from this, use the dot program. For example, to make a PDF file do the following:"<<endl
0419     <<endl
0420     <<"   dot -Tpdf jana.dot -o jana.pdf"<<endl
0421     <<endl
0422     <<"This should give you a file named \"jana.pdf\"."<<endl
0423     <<endl;
0424 }
0425
0426 //------------------------------------------------------------------
0427 // FindDecendents
0428 //------------------------------------------------------------------
0429 void JEventProcessorJANADOT::FindDecendents(string caller, set<string> &decendents)
0430 {
0431     /// The is reentrant and will call itself until all decendents of the
0432     /// given caller are recorded in decendents
0433
0434     decendents.insert(caller);
0435
0436     map<CallLink, CallStats>::iterator iter;
0437     for(iter=call_links.begin(); iter!=call_links.end(); iter++){
0438         const CallLink &link = iter->first;
0439
0440         string mycaller = MakeNametag(link.caller_name, link.caller_tag);
0441         string mycallee = MakeNametag(link.callee_name, link.callee_tag);
0442
0443         if(mycaller == caller) FindDecendents(mycallee, decendents);
0444     }
0445
0446 }
0447
0448 //------------------------------------------------------------------
0449 // FindAncestors
0450 //------------------------------------------------------------------
0451 void JEventProcessorJANADOT::FindAncestors(string callee, set<string> &ancestors)
0452 {
0453     /// The is reentrant and will call itself until all decendents of the
0454     /// given caller are recorded in decendents
0455
0456     ancestors.insert(callee);
0457
0458     map<CallLink, CallStats>::iterator iter;
0459     for(iter=call_links.begin(); iter!=call_links.end(); iter++){
0460         const CallLink &link = iter->first;
0461
0462         string mycaller = MakeNametag(link.caller_name, link.caller_tag);
0463         string mycallee = MakeNametag(link.callee_name, link.callee_tag);
0464
0465         if(mycallee == callee) FindAncestors(mycaller, ancestors);
0466     }
0467
0468 }
0469
0470 //------------------------------------------------------------------
0471 // MakeTimeString
0472 //------------------------------------------------------------------
0473 string JEventProcessorJANADOT::MakeTimeString(double time_in_ms)
0474 {
0475     double order=log10(time_in_ms);
0476     stringstream ss;
0477     ss<<fixed<<setprecision(2);
0478     if(order<0){
0479         ss<<time_in_ms*1000.0<<" us";
0480     }else if(order<=2.0){
0481         ss<<time_in_ms<<" ms";
0482     }else{
0483         ss<<time_in_ms/1000.0<<" s";
0484     }
0485
0486     return ss.str();
0487 }
0488
0489 //------------------------------------------------------------------
0490 // MakeNametag
0491 //------------------------------------------------------------------
0492 string JEventProcessorJANADOT::MakeNametag(const string &name, const string &tag)
0493 {
0494     string nametag = name;
0495     if(tag.size()>0)nametag += ":"+tag;
0496
0497     nametag = std::regex_replace(nametag, std::regex("<"), "&lt;");
0498     nametag = std::regex_replace(nametag, std::regex(">"), "&gt;");
0499
0500     return nametag;
0501 }
0502