Project

General

Profile

« Previous | Next » 

Revision 3252

Added by Jing Tao over 17 years ago

Add time debug information for query.

View differences:

src/edu/ucsb/nceas/metacat/DBQuery.java
302 302
      else
303 303
      {
304 304
        //knb format, in this case we will get whole result and sent it out
305
        response.setContentType("text/html");
305
    	response.setContentType("text/html");
306 306
        PrintWriter nonout = null;
307 307
        StringBuffer xml = createResultDocument(xmlquery, qspec, nonout, user,
308 308
                                                groups, useXMLIndex, pagesize, 
......
311 311
        //transfer the xml to html
312 312
        try
313 313
        {
314

  
314
         double startHTMLTransform = System.currentTimeMillis()/1000;
315 315
         DBTransform trans = new DBTransform();
316 316
         response.setContentType("text/html");
317 317

  
......
324 324
         trans.transformXMLDocument(xml.toString(), "-//NCEAS//resultset//EN",
325 325
                                 "-//W3C//HTML//EN", qformat, out, params,
326 326
                                 sessionid);
327

  
327
         double endHTMLTransform = System.currentTimeMillis()/1000;
328
         logMetacat.warn("The time for transfering resultset from xml to html format is "
329
        		                             +(endHTMLTransform -startHTMLTransform));
328 330
        }
329 331
        catch(Exception e)
330 332
        {
......
453 455
                                      int pagesize, int pagestart, String sessionid)
454 456
                                      throws Exception
455 457
    {
458
      double startSelectionTime = System.currentTimeMillis()/1000;
456 459
      String query = null;
457 460
      int count = 0;
458 461
      int index = 0;
......
530 533
      rs = pstmt.executeQuery();
531 534

  
532 535
      double queryExecuteTime = System.currentTimeMillis() / 1000;
533
      logMetacat.warn("Time to execute query: "
536
      logMetacat.warn("Time to execute select docid query is "
534 537
                    + (queryExecuteTime - startTime));
535 538

  
536 539
      boolean tableHasRows = rs.next();
......
562 565
             && !qspec.isPercentageSearch())
563 566
         {
564 567
           logMetacat.warn("Back tracing now...");
568
           double startBackTracingTime = System.currentTimeMillis()/1000;
565 569
           String sep = MetaCatUtil.getOption("accNumSeparator");
566 570
           StringBuffer btBuf = new StringBuffer();
567 571
           btBuf.append("select docid from xml_relation where ");
......
665 669
              }//while
666 670
              npstmt.close();
667 671
              btrs.close();
672
              double endBackTracingTime = System.currentTimeMillis()/1000;
673
              logMetacat.warn("Back tracing time for one doc is "+
674
            		               (endBackTracingTime - startBackTracingTime));
668 675
        }
669 676
        else if (returndocVec.size() == 0 || returndocVec.contains(doctype))
670 677
        {
......
735 742
     
736 743
     rs.close();
737 744
     pstmt.close();
745
     double docListTime = System.currentTimeMillis() / 1000;
746
     logMetacat.warn("======Total time to get docid list is: "
747
                    + (docListTime - startSelectionTime ));
738 748
     //if docListResult is not empty, it need to be sent.
739 749
     if (docListResult.size() != 0)
740 750
     {
741 751
       handleSubsetResult(qspec,resultsetBuffer, out, docListResult,
742 752
                              user, groups,dbconn, useXMLIndex);
753
       double returnFieldTime = System.currentTimeMillis() / 1000;
754
       logMetacat.warn("======Total time to get return fields is: "
755
                      + (returnFieldTime - docListTime));
743 756
     }
744
     double docListTime = System.currentTimeMillis() / 1000;
745
     logMetacat.warn("prepare docid list time: "
746
                    + (docListTime - queryExecuteTime));
757
     
747 758

  
748 759
     return resultsetBuffer;
749 760
    }//findReturnDoclist
......
763 774
     
764 775
     // check if there is a record in xml_returnfield
765 776
     // and get the returnfield_id and usage count
777
    double startGetReturnValueFromQueryresultable = System.currentTimeMillis()/1000;
766 778
     int usage_count = getXmlReturnfieldsTableId(qspec, dbconn);
767 779
     boolean enterRecords = false;
768 780

  
......
776 788
     if(usage_count > count){
777 789
         enterRecords = true;
778 790
     }
779

  
791
     
780 792
     if(returnfield_id < 0){
781 793
         logMetacat.warn("Error in getting returnfield id from"
782 794
                                  + "xml_returnfield table");
......
788 800
     logMetacat.info("size of partOfDoclist before"
789 801
                             + " docidsInQueryresultTable(): "
790 802
                             + partOfDoclist.size());
803
     
791 804
     Hashtable queryresultDocList = docidsInQueryresultTable(returnfield_id,
792 805
                                                        partOfDoclist, dbconn);
793 806

  
......
796 809
     while (_keys.hasMoreElements()){
797 810
         partOfDoclist.remove((String)_keys.nextElement());
798 811
     }
799

  
812
     double endGetReturnValueFromQueryresultable = System.currentTimeMillis()/1000;
813
     logMetacat.warn("Time to get return fields from xml_queryresult table is (Part1 in return fields) " +
814
    		               (endGetReturnValueFromQueryresultable-startGetReturnValueFromQueryresultable));
800 815
     // backup the keys-elements in partOfDoclist to check later
801 816
     // if the doc entry is indexed yet
802 817
     Hashtable partOfDoclistBackup = new Hashtable();
......
813 828
     //add return fields for the documents in partOfDoclist
814 829
     partOfDoclist = addReturnfield(partOfDoclist, qspec, user, groups,
815 830
                                        dbconn, useXMLIndex);
831
     double endExtendedQuery = System.currentTimeMillis()/1000;
832
     logMetacat.warn("Time to get return fields through execute extended query (Part2 in return fields) "
833
    		                                          + (endExtendedQuery - endGetReturnValueFromQueryresultable));
816 834
     //add relationship part part docid list for the documents in partOfDocList
817 835
     partOfDoclist = addRelationship(partOfDoclist, qspec, dbconn, useXMLIndex);
818 836

  
819

  
837
     double startStoreReturnField = System.currentTimeMillis()/1000;
820 838
     Iterator keys = partOfDoclist.getDocids();
821 839
     String key = null;
822 840
     String element = null;
......
848 866
             pstmt.execute();
849 867
             pstmt.close();
850 868
         }
851

  
869
         double endStoreReturnField = System.currentTimeMillis()/1000;
870
         logMetacat.warn("Time to store new return fields into xml_queryresult table (Part4 in return fields) "
871
                 + (endStoreReturnField -startStoreReturnField));
852 872
         // A string with element
853 873
         String xmlElement = "  <document>" + element + "</document>";
854

  
874
        
855 875
         //send single element to output
856 876
         if (out != null)
857 877
         {
......
1092 1112
            tableHasRows = rs.next();
1093 1113
          }*/
1094 1114

  
1095
           double extendedAccessQueryEnd = System.currentTimeMillis() / 1000;
1115
          /* double extendedAccessQueryEnd = System.currentTimeMillis() / 1000;
1096 1116
           logMetacat.info( "Time for execute access extended query: "
1097
                          + (extendedAccessQueryEnd - extendedQueryStart));
1117
                          + (extendedAccessQueryEnd - extendedQueryStart));*/
1098 1118

  
1099 1119
           String extendedQuery =
1100 1120
               qspec.printExtendedSQL(doclist.toString(), useXMLIndex);
......
1210 1230
    StringBuffer document = null;
1211 1231
    double startRelation = System.currentTimeMillis() / 1000;
1212 1232
    Iterator docidkeys = docListResult.getDocids();
1233
    //System.out.println("!!!!!!!!!!!!!!!!!!!!!!!!1beofre the while loop the docid keys is "+docidkeys);
1213 1234
    while (docidkeys.hasNext())
1214 1235
    {
1215 1236
      //String connstring =
1216 1237
      // "metacat://"+util.getOption("server")+"?docid=";
1217 1238
      String connstring = "%docid=";
1239
      //System.out.println("!!!!!!!!!!!!!!!!!!!!!!!!1beofre the null line the docid keys is "+docidkeys);
1218 1240
      String docidkey = (String) docidkeys.next();
1241
      //System.out.println("!!!!!!!!!!!!!!!!!!!!!!!!1after the null line the docid string is "+docidkey);
1219 1242
      pstmt = dbconn.prepareStatement(QuerySpecification
1220 1243
                      .printRelationSQL(docidkey));
1221 1244
      pstmt.execute();
......
1257 1280
      pstmt.close();
1258 1281
    }//while
1259 1282
    double endRelation = System.currentTimeMillis() / 1000;
1260
    logMetacat.info("Time for adding relation to docListResult: "
1283
    logMetacat.info("Time to add relationship to return fields (part 3 in return fields): "
1261 1284
                             + (endRelation - startRelation));
1262 1285

  
1263 1286
    return docListResult;

Also available in: Unified diff