Project

General

Profile

« Previous | Next » 

Revision 5165

Added by daigle about 15 years ago

add method name to log messages and create configured thresholds for warning messages

View differences:

lib/metacat.properties
73 73
database.maximumConnectionAge=120000
74 74
database.maximumConnectionTime=60000
75 75
database.maximumUsageNumber=100
76
database.connectionCountWarnLimit=15
76 77
database.numberOfIndexingThreads=5
77 78
database.indexingTimerTaskTime=604800000
78 79
database.indexingInitialDelay=3600000
......
97 98
database.queryresultCacheSize=500
98 99
#turn on or off the query result cache
99 100
database.queryCacheOn=true
101
#the time in milliseconds that an squery can run before metacat logs a warning
102
database.queryTimeWarnLimit=30000
103
#the time in milliseconds that an squery can run before metacat logs a warning
104
database.squeryTimeWarnLimit=30000
100 105

  
106

  
107
######## DB Query section              #######################################
108
#the time in milliseconds that a stylesheet transform can run before metacat logs a warning
109
dbquery.transformTimeWarnLimit=60000
110
#the time in milliseconds to get a document list before metacat logs a warning
111
dbquery.findDocListTimeWarnLimit=60000
112
#the time in milliseconds to get return values from queryresults table before metacat logs a warning
113
dbquery.findQueryResultsTimeWarnLimit=60000
114
#the time in milliseconds to run extended (index and node) queries before metacat logs a warning
115
dbquery.extendedQueryRunTimeWarnLimit=60000
116
#the time in milliseconds to store return fields before metacat logs a warning
117
dbquery.storeReturnFieldTimeWarnLimit=60000
118
#the time in milliseconds to totally process return fields before metacat logs a warning
119
dbquery.totalReturnFieldTimeWarnLimit=120000
120

  
101 121
######## Datamanager section              #######################################
102 122
datamanager.adapter=PostgresAdapter
103 123
datamanager.implementation=edu.ucsb.nceas.metacat.dataquery.PostgresDatabaseConnectionPool
src/edu/ucsb/nceas/metacat/DBQuery.java
239 239
    	// since the query will be too long to be handled, so we divided the 
240 240
    	// docids vector into couple vectors.
241 241
    	int size = (new Integer(PropertyService.getProperty("database.appResultsetSize"))).intValue();
242
    	logMetacat.info("The size of select doicds is "+docids.size());
243
    	logMetacat.info("The application result size in metacat.properties is "+size);
242
    	logMetacat.info("DBQuery.DBQuery - The size of select doicds is "+docids.size());
243
    	logMetacat.info("DBQuery.DBQuery - The application result size in metacat.properties is "+size);
244 244
    	Vector subset = new Vector();
245 245
    	if (docids != null && docids.size() > size)
246 246
    	{
......
313 313
    {
314 314
      int pagesize = 0;
315 315
      int pagestart = 0;
316
      long transferWarnLimit = 0; 
316 317
      
317 318
      if(params.containsKey("pagesize") && params.containsKey("pagestart"))
318 319
      {
......
331 332
      try {
332 333
    	xmlquery = ((String[])params.get("query"))[0];
333 334

  
334
        logMetacat.info("SESSIONID: " + sessionid);
335
        logMetacat.info("xmlquery: " + xmlquery);
335
        logMetacat.info("DBQuery.findDocuments - SESSIONID: " + sessionid);
336
        logMetacat.info("DBQuery.findDocuments - xmlquery: " + xmlquery);
336 337
        qformat = ((String[])params.get("qformat"))[0];
337
        logMetacat.info("qformat: " + qformat);
338
        logMetacat.info("DBQuery.findDocuments - qformat: " + qformat);
338 339
      }
339 340
      catch (Exception ee)
340 341
      {
341
        logMetacat.error("Couldn't retrieve xmlquery or qformat value from "
342
        logMetacat.error("DBQuery.findDocuments - Couldn't retrieve xmlquery or qformat value from "
342 343
                  +"params hashtable in DBQuery.findDocuments: "
343 344
                  + ee.getMessage()); 
344 345
      }
......
355 356
         }
356 357
         catch (Exception ee)
357 358
         {
358
           logMetacat.error("error generating QuerySpecification object"
359
                                    +" in DBQuery.findDocuments"
359
           logMetacat.error("DBQuery.findDocuments - error generating QuerySpecification object: "
360 360
                                    + ee.getMessage());
361 361
         }
362 362
      }
......
382 382
        //transfer the xml to html
383 383
        try
384 384
        {
385
         double startHTMLTransform = System.currentTimeMillis()/1000;
385
         long startHTMLTransform = System.currentTimeMillis();
386 386
         DBTransform trans = new DBTransform();
387 387
         response.setContentType("text/html");
388 388

  
......
395 395
         trans.transformXMLDocument(xml.toString(), "-//NCEAS//resultset//EN",
396 396
                                 "-//W3C//HTML//EN", qformat, out, params,
397 397
                                 sessionid);
398
         double endHTMLTransform = System.currentTimeMillis()/1000;
399
          logMetacat.warn("The time to transfrom resultset from xml to html format is "
400
                  		                             +(endHTMLTransform -startHTMLTransform));
398
         long transformRunTime = System.currentTimeMillis() - startHTMLTransform;
399
         
400
         transferWarnLimit = Long.parseLong(PropertyService.getProperty("dbquery.transformTimeWarnLimit"));
401
         
402
         if (transformRunTime > transferWarnLimit) {
403
         	logMetacat.warn("DBQuery.findDocuments - The time to transfrom resultset from xml to html format is "
404
                  		                             + transformRunTime);
405
         }
401 406
          MetacatUtil.writeDebugToFile("---------------------------------------------------------------------------------------------------------------Transfrom xml to html  "
402
                             +(endHTMLTransform -startHTMLTransform));
403
          MetacatUtil.writeDebugToDelimiteredFile(" "+(endHTMLTransform -startHTMLTransform), false);
407
                             + transformRunTime);
408
          MetacatUtil.writeDebugToDelimiteredFile(" " + transformRunTime, false);
404 409
        }
405 410
        catch(Exception e)
406 411
        {
407
         logMetacat.error("Error in MetaCatServlet.transformResultset:"
412
         logMetacat.error("DBQuery.findDocuments - Error in MetaCatServlet.transformResultset:"
408 413
                                +e.getMessage());
409 414
         }
410 415

  
......
485 490
        StringBuffer resultContent = new StringBuffer();
486 491
        if (docidOverride == null || docidOverride.size() == 0)
487 492
        {
488
        	logMetacat.info("Not in map query");
493
        	logMetacat.debug("DBQuery.createResultDocument - Not in map query");
489 494
        	resultContent = findResultDoclist(qspec, out, user, groups,
490 495
                    dbconn, useXMLIndex, pagesize, pagestart, 
491 496
                    sessionid, givenDocids);
492 497
        }
493 498
        else
494 499
        {
495
        	logMetacat.info("In map query");
500
        	logMetacat.debug("DBQuery.createResultDocument - In map query");
496 501
        	// since docid can be too long to be handled. We divide it into several parts
497 502
        	for (int i= 0; i<docidOverride.size(); i++)
498 503
        	{
499
        	   logMetacat.info("in loop===== "+i);
504
        	   logMetacat.debug("DBQuery.createResultDocument - in loop===== "+i);
500 505
        		givenDocids = (Vector)docidOverride.elementAt(i);
501 506
        		StringBuffer subset = findResultDoclist(qspec, out, user, groups,
502 507
                        dbconn, useXMLIndex, pagesize, pagestart, 
......
509 514
      } //try
510 515
      catch (IOException ioe)
511 516
      {
512
        logMetacat.error("IO error in DBQuery.findDocuments:");
513
        logMetacat.error(ioe.getMessage());
514

  
517
        logMetacat.error("DBQuery.createResultDocument - IO error: " + ioe.getMessage());
515 518
      }
516 519
      catch (SQLException e)
517 520
      {
518
        logMetacat.error("SQL Error in DBQuery.findDocuments: "
519
                                 + e.getMessage());
521
        logMetacat.error("DBQuery.createResultDocument - SQL Error: " + e.getMessage());
520 522
      }
521 523
      catch (Exception ee)
522 524
      {
523
        logMetacat.error("Exception in DBQuery.findDocuments: "
525
        logMetacat.error("DBQuery.createResultDocument - General exception: "
524 526
                                 + ee.getMessage());
525 527
        ee.printStackTrace();
526 528
      }
......
566 568
      int rev = 0;
567 569
      double startTime = 0;
568 570
      int offset = 1;
569
      double startSelectionTime = System.currentTimeMillis()/1000;
571
      long startSelectionTime = System.currentTimeMillis();
570 572
      ResultSet rs = null;
571 573
           
572 574
   
......
594 596
      if ( givenDocids == null || givenDocids.size() == 0 ) {
595 597
          query = qspec.printSQL(useXMLIndex);
596 598
      } else {
597
          logMetacat.info("*** docid override " + givenDocids.size());
599
          logMetacat.info("DBQuery.findResultDoclist - docid override " + givenDocids.size());
598 600
          StringBuffer queryBuffer = new StringBuffer( "SELECT docid,docname,doctype,date_created, date_updated, rev " );
599 601
          queryBuffer.append( " FROM xml_documents WHERE docid IN (" );
600 602
          for (int i = 0; i < givenDocids.size(); i++) {  
......
608 610
      } 
609 611
      String ownerQuery = getOwnerQuery(user);
610 612
      //logMetacat.debug("query: " + query);
611
      logMetacat.debug("owner query: "+ownerQuery);
613
      logMetacat.debug("DBQuery.findResultDoclist - owner query: " + ownerQuery);
612 614
      // if query is not the owner query, we need to check the permission
613 615
      // otherwise we don't need (owner has all permission by default)
614 616
      if (!query.equals(ownerQuery))
......
625 627
        }
626 628
        
627 629
      }
628
      logMetacat.debug("============ final selection query: " + query);
630
      logMetacat.debug("DBQuery.findResultDoclist - final selection query: " + query);
629 631
      String selectionAndExtendedQuery = null;
630 632
      // we only get cache for public
631 633
      if (user != null && user.equalsIgnoreCase("public") 
......
633 635
      {
634 636
    	  selectionAndExtendedQuery = query +qspec.getReturnDocList()+qspec.getReturnFieldList();
635 637
   	      String cachedResult = getResultXMLFromCache(selectionAndExtendedQuery);
636
   	      logMetacat.debug("The key of query cache is "+selectionAndExtendedQuery);
638
   	      logMetacat.debug("DBQuery.findResultDoclist - The key of query cache is " + selectionAndExtendedQuery);
637 639
   	      //System.out.println("==========the string from cache is "+cachedResult);
638 640
   	      if (cachedResult != null)
639 641
   	      {
640
   	    	logMetacat.info("result from cache !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!");
642
   	    	logMetacat.info("DBQuery.findResultDoclist - result from cache !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!");
641 643
   	    	 if (out != null)
642 644
   	         {
643 645
   	             out.println(cachedResult);
......
652 654
      rs = pstmt.executeQuery();
653 655

  
654 656
      double queryExecuteTime = System.currentTimeMillis() / 1000;
655
      logMetacat.debug("Time to execute select docid query is "
657
      logMetacat.debug("DBQuery.findResultDoclist - Time to execute select docid query is "
656 658
                    + (queryExecuteTime - startTime));
657 659
      MetacatUtil.writeDebugToFile("\n\n\n\n\n\nExecute selection query  "
658 660
              + (queryExecuteTime - startTime));
......
669 671
      int currentIndex = 0;
670 672
      while (tableHasRows)
671 673
      {
672
        logMetacat.debug("############getting result: " + currentIndex);
674
        logMetacat.debug("DBQuery.findResultDoclist - getting result: " + currentIndex);
673 675
        docid = rs.getString(1).trim();
674
        logMetacat.debug("############processing: " + docid);
676
        logMetacat.debug("DBQuery.findResultDoclist -  processing: " + docid);
675 677
        docname = rs.getString(2);
676 678
        doctype = rs.getString(3);
677
        logMetacat.debug("############processing: " + doctype);
679
        logMetacat.debug("DBQuery.findResultDoclist - processing: " + doctype);
678 680
        createDate = rs.getString(4);
679 681
        updateDate = rs.getString(5);
680 682
        rev = rs.getInt(6);
......
682 684
         Vector returndocVec = qspec.getReturnDocList();
683 685
       if (returndocVec.size() == 0 || returndocVec.contains(doctype))
684 686
        {
685
          logMetacat.debug("NOT Back tracing now...");
687
          logMetacat.debug("DBQuery.findResultDoclist - NOT Back tracing now...");
686 688
           document = new StringBuffer();
687 689

  
688 690
           String completeDocid = docid
......
709 711
           
710 712
           docListResult.addResultDocument(
711 713
             new ResultDocument(docid, (String) document.toString()));
712
           logMetacat.info("$$$$$$$real result: " + docid);
714
           logMetacat.info("DBQuery.findResultDoclist - real result: " + docid);
713 715
           currentIndex++;
714 716
           count++;
715 717
        }//else
......
727 729
          docListResult = new ResultDocumentSet();
728 730
        }
729 731
       
730
       logMetacat.debug("currentIndex: " + currentIndex);
731
       logMetacat.debug("page comparator: " + (pagesize * pagestart) + pagesize);
732
       logMetacat.debug("DBQuery.findResultDoclist - currentIndex: " + currentIndex);
733
       logMetacat.debug("DBQuery.findResultDoclist - page comparator: " + (pagesize * pagestart) + pagesize);
732 734
       if(currentIndex >= ((pagesize * pagestart) + pagesize))
733 735
       {
734 736
         ResultDocumentSet pagedResultsHash = new ResultDocumentSet();
......
762 764
     
763 765
     rs.close();
764 766
     pstmt.close();
765
     double docListTime = System.currentTimeMillis() / 1000;
766
     logMetacat.warn("======Total time to get docid list is: "
767
                          + (docListTime - startSelectionTime ));
767
     long docListTime = System.currentTimeMillis() - startSelectionTime;
768
     long docListWarnLimit = Long.parseLong(PropertyService.getProperty("dbquery.findDocListTimeWarnLimit"));
769
     if (docListTime > docListWarnLimit) {
770
    	 logMetacat.warn("DBQuery.findResultDoclist - Total time to get docid list is: "
771
                          + docListTime);
772
     }
768 773
     MetacatUtil.writeDebugToFile("---------------------------------------------------------------------------------------------------------------Total selection: "
769
             + (docListTime - startSelectionTime ));
770
     MetacatUtil.writeDebugToDelimiteredFile(" "+ (docListTime - startSelectionTime ), false);
774
             + docListTime);
775
     MetacatUtil.writeDebugToDelimiteredFile(" "+ docListTime, false);
771 776
     //if docListResult is not empty, it need to be sent.
772 777
     if (docListResult.size() != 0)
773 778
     {
......
805 810
                                       DBConnection dbconn, boolean useXMLIndex)
806 811
                                       throws Exception
807 812
   {
808
     double startReturnField = System.currentTimeMillis()/1000;
813
     double startReturnFieldTime = System.currentTimeMillis();
809 814
     // check if there is a record in xml_returnfield
810 815
     // and get the returnfield_id and usage count
811 816
     int usage_count = getXmlReturnfieldsTableId(qspec, dbconn);
......
823 828
     }
824 829

  
825 830
     if(returnfield_id < 0){
826
         logMetacat.warn("Error in getting returnfield id from"
831
         logMetacat.warn("DBQuery.handleSubsetResult - Error in getting returnfield id from"
827 832
                                  + "xml_returnfield table");
828 833
         enterRecords = false;
829 834
     }
830 835

  
831 836
     // get the hashtable containing the docids that already in the
832 837
     // xml_queryresult table
833
     logMetacat.info("size of partOfDoclist before"
838
     logMetacat.info("DBQuery.handleSubsetResult - size of partOfDoclist before"
834 839
                             + " docidsInQueryresultTable(): "
835 840
                             + partOfDoclist.size());
836
     double startGetReturnValueFromQueryresultable = System.currentTimeMillis()/1000;
841
     long startGetReturnValueFromQueryresultable = System.currentTimeMillis();
837 842
     Hashtable queryresultDocList = docidsInQueryresultTable(returnfield_id,
838 843
                                                        partOfDoclist, dbconn);
839 844

  
......
842 847
     while (_keys.hasMoreElements()){
843 848
         partOfDoclist.remove((String)_keys.nextElement());
844 849
     }
845
     double endGetReturnValueFromQueryresultable = System.currentTimeMillis()/1000;
846
     logMetacat.warn("Time to get return fields from xml_queryresult table is (Part1 in return fields) " +
847
          		               (endGetReturnValueFromQueryresultable-startGetReturnValueFromQueryresultable));
850
     
851
     long queryResultReturnValuetime = System.currentTimeMillis() - startGetReturnValueFromQueryresultable;
852
     long queryResultWarnLimit = 
853
    	 Long.parseLong(PropertyService.getProperty("dbquery.findQueryResultsTimeWarnLimit"));
854
     
855
     if (queryResultReturnValuetime > queryResultWarnLimit) {
856
    	 logMetacat.warn("DBQuery.handleSubsetResult - Time to get return fields from xml_queryresult table is (Part1 in return fields) " +
857
    		 queryResultReturnValuetime);
858
     }
848 859
     MetacatUtil.writeDebugToFile("-----------------------------------------Get fields from xml_queryresult(Part1 in return fields) " +
849
               (endGetReturnValueFromQueryresultable-startGetReturnValueFromQueryresultable));
850
     MetacatUtil.writeDebugToDelimiteredFile(" " +
851
             (endGetReturnValueFromQueryresultable-startGetReturnValueFromQueryresultable),false);
860
    		 queryResultReturnValuetime);
861
     MetacatUtil.writeDebugToDelimiteredFile(" " + queryResultReturnValuetime,false);
862
     
863
     long startExtendedQuery = System.currentTimeMillis();
852 864
     // backup the keys-elements in partOfDoclist to check later
853 865
     // if the doc entry is indexed yet
854 866
     Hashtable partOfDoclistBackup = new Hashtable();
......
858 870
         partOfDoclistBackup.put(key, partOfDoclist.get(key));
859 871
     }
860 872

  
861
     logMetacat.info("size of partOfDoclist after"
873
     logMetacat.info("DBQuery.handleSubsetResult - size of partOfDoclist after"
862 874
                             + " docidsInQueryresultTable(): "
863 875
                             + partOfDoclist.size());
864 876

  
865 877
     //add return fields for the documents in partOfDoclist
866 878
     partOfDoclist = addReturnfield(partOfDoclist, qspec, user, groups,
867 879
                                        dbconn, useXMLIndex);
868
     double endExtendedQuery = System.currentTimeMillis()/1000;
869
     logMetacat.warn("Get fields from index and node table (Part2 in return fields) "
870
        		                                          + (endExtendedQuery - endGetReturnValueFromQueryresultable));
880
     long extendedQueryRunTime = startExtendedQuery - System.currentTimeMillis();
881
     long extendedQueryWarnLimit = 
882
    	 Long.parseLong(PropertyService.getProperty("dbquery.extendedQueryRunTimeWarnLimit"));
883
  
884
     if (extendedQueryRunTime > extendedQueryWarnLimit) {
885
    	 logMetacat.warn("DBQuery.handleSubsetResult - Get fields from index and node table (Part2 in return fields) "
886
        		                                          + extendedQueryRunTime);
887
     }
871 888
     MetacatUtil.writeDebugToFile("-----------------------------------------Get fields from extened query(Part2 in return fields) "
872
             + (endExtendedQuery - endGetReturnValueFromQueryresultable));
889
             + extendedQueryRunTime);
873 890
     MetacatUtil.writeDebugToDelimiteredFile(" "
874
             + (endExtendedQuery - endGetReturnValueFromQueryresultable), false);
891
             + extendedQueryRunTime, false);
875 892
     //add relationship part part docid list for the documents in partOfDocList
876 893
     //partOfDoclist = addRelationship(partOfDoclist, qspec, dbconn, useXMLIndex);
877 894

  
878
     double startStoreReturnField = System.currentTimeMillis()/1000;
895
     long startStoreReturnField = System.currentTimeMillis();
879 896
     Iterator keys = partOfDoclist.getDocids();
880 897
     String key = null;
881 898
     String element = null;
......
910 927
             }
911 928
             catch(Exception e)
912 929
             {
913
            	 logMetacat.warn("couldn't insert the element to xml_queryresult table "+e.getLocalizedMessage());
930
            	 logMetacat.warn("DBQuery.handleSubsetResult - couldn't insert the element to xml_queryresult table "+e.getLocalizedMessage());
914 931
             }
915 932
             finally
916 933
             {
......
929 946
         resultset.append(xmlElement);
930 947
     }//while
931 948
     
932
     double endStoreReturnField = System.currentTimeMillis()/1000;
933
     logMetacat.warn("Time to store new return fields into xml_queryresult table (Part4 in return fields) "
934
                   + (endStoreReturnField -startStoreReturnField));
949
     double storeReturnFieldTime = System.currentTimeMillis() - startStoreReturnField;
950
     long storeReturnFieldWarnLimit = 
951
    	 Long.parseLong(PropertyService.getProperty("dbquery.storeReturnFieldTimeWarnLimit"));
952

  
953
     if (storeReturnFieldTime > storeReturnFieldWarnLimit) {
954
    	 logMetacat.warn("DBQuery.handleSubsetResult - Time to store new return fields into xml_queryresult table (Part4 in return fields) "
955
                   + storeReturnFieldTime);
956
     }
935 957
     MetacatUtil.writeDebugToFile("-----------------------------------------Insert new record to xml_queryresult(Part4 in return fields) "
936
             + (endStoreReturnField -startStoreReturnField));
937
     MetacatUtil.writeDebugToDelimiteredFile(" "
938
             + (endStoreReturnField -startStoreReturnField), false);
958
             + storeReturnFieldTime);
959
     MetacatUtil.writeDebugToDelimiteredFile(" " + storeReturnFieldTime, false);
939 960
     
940 961
     Enumeration keysE = queryresultDocList.keys();
941 962
     while (keysE.hasMoreElements())
......
951 972
         }
952 973
         resultset.append(xmlElement);
953 974
     }//while
954
     double returnFieldTime = System.currentTimeMillis() / 1000;
955
     logMetacat.warn("======Total time to get return fields is: "
956
                           + (returnFieldTime - startReturnField));
957
     MetacatUtil.writeDebugToFile("---------------------------------------------------------------------------------------------------------------"+
958
    		 "Total to get return fields  "
959
                                   + (returnFieldTime - startReturnField));
960
     MetacatUtil.writeDebugToDelimiteredFile(" "+ (returnFieldTime - startReturnField), false);
975
     double returnFieldTime = System.currentTimeMillis() - startReturnFieldTime;
976
     long totalReturnFieldWarnLimit = 
977
    	 Long.parseLong(PropertyService.getProperty("dbquery.totalReturnFieldTimeWarnLimit"));
978

  
979
     if (returnFieldTime > totalReturnFieldWarnLimit) {
980
    	 logMetacat.warn("DBQuery.handleSubsetResult - Total time to get return fields is: "
981
                           + returnFieldTime);
982
     }
983
     MetacatUtil.writeDebugToFile("DBQuery.handleSubsetResult - ---------------------------------------------------------------------------------------------------------------"+
984
    		 "Total to get return fields  " + returnFieldTime);
985
     MetacatUtil.writeDebugToDelimiteredFile("DBQuery.handleSubsetResult - "+ returnFieldTime, false);
961 986
     return resultset;
962 987
 }
963 988

  
......
992 1017
             String query = "select docid, queryresult_string from "
993 1018
                          + "xml_queryresult where returnfield_id = " +
994 1019
                          returnfield_id +" and docid in ("+ doclist + ")";
995
             logMetacat.info("Query to get docids from xml_queryresult:"
1020
             logMetacat.info("DBQuery.docidsInQueryresultTable - Query to get docids from xml_queryresult:"
996 1021
                                      + query);
997 1022

  
998 1023
             try {
......
1010 1035
                     if(element != null){
1011 1036
                         returnValue.put(key, element);
1012 1037
                     } else {
1013
                         logMetacat.info("Null elment found ("
1038
                         logMetacat.info("DBQuery.docidsInQueryresultTable - Null elment found ("
1014 1039
                         + "DBQuery.docidsInQueryresultTable)");
1015 1040
                     }
1016 1041
                     tableHasRows = rs.next();
......
1018 1043
                 rs.close();
1019 1044
                 pstmt.close();
1020 1045
             } catch (Exception e){
1021
                 logMetacat.error("Error getting docids from "
1022
                                          + "queryresult in "
1023
                                          + "DBQuery.docidsInQueryresultTable: "
1024
                                          + e.getMessage());
1046
                 logMetacat.error("DBQuery.docidsInQueryresultTable - Error getting docids from "
1047
                                          + "queryresult: " + e.getMessage());
1025 1048
              }
1026 1049
         }
1027 1050
         return returnValue;
......
1044 1067
       // query for finding the id from xml_returnfield
1045 1068
       String query = "SELECT returnfield_id, usage_count FROM xml_returnfield "
1046 1069
            + "WHERE returnfield_string LIKE ?";
1047
       logMetacat.info("ReturnField Query:" + query);
1070
       logMetacat.info("DBQuery.getXmlReturnfieldsTableId - ReturnField Query:" + query);
1048 1071

  
1049 1072
       try {
1050 1073
           // prepare and run the query
......
1067 1090
               // increase the usage count
1068 1091
               query = "UPDATE xml_returnfield SET usage_count ='" + count
1069 1092
                   + "' WHERE returnfield_id ='"+ id +"'";
1070
               logMetacat.info("ReturnField Table Update:"+ query);
1093
               logMetacat.info("DBQuery.getXmlReturnfieldsTableId - ReturnField Table Update:"+ query);
1071 1094

  
1072 1095
               pstmt = dbconn.prepareStatement(query);
1073 1096
               dbconn.increaseUsageCount(1);
......
1081 1104
               // insert a new record
1082 1105
               query = "INSERT INTO xml_returnfield (returnfield_string, usage_count)"
1083 1106
                   + "VALUES (?, '1')";
1084
               logMetacat.info("ReturnField Table Insert:"+ query);
1107
               logMetacat.info("DBQuery.getXmlReturnfieldsTableId - ReturnField Table Insert:"+ query);
1085 1108
               pstmt = dbconn.prepareStatement(query);
1086 1109
               pstmt.setString(1, returnfield);
1087 1110
               dbconn.increaseUsageCount(1);
......
1091 1114
               // get the id of the new record
1092 1115
               query = "SELECT returnfield_id FROM xml_returnfield "
1093 1116
                   + "WHERE returnfield_string LIKE ?";
1094
               logMetacat.info("ReturnField query after Insert:" + query);
1117
               logMetacat.info("DBQuery.getXmlReturnfieldsTableId - ReturnField query after Insert:" + query);
1095 1118
               pstmt = dbconn.prepareStatement(query);
1096 1119
               pstmt.setString(1, returnfield);
1097 1120

  
......
1108 1131
           }
1109 1132

  
1110 1133
       } catch (Exception e){
1111
           logMetacat.error("Error getting id from xml_returnfield in "
1134
           logMetacat.error("DBQuery.getXmlReturnfieldsTableId - Error getting id from xml_returnfield in "
1112 1135
                                     + "DBQuery.getXmlReturnfieldsTableId: "
1113 1136
                                     + e.getMessage());
1114 1137
           id = -1;
......
1161 1184

  
1162 1185
           String extendedQuery =
1163 1186
               qspec.printExtendedSQL(doclist.toString(), useXMLIndex);
1164
           logMetacat.info("Extended query: " + extendedQuery);
1187
           logMetacat.info("DBQuery.addReturnfield - Extended query: " + extendedQuery);
1165 1188

  
1166 1189
           if(extendedQuery != null){
1167
        	   double extendedQueryStart = System.currentTimeMillis() / 1000;
1190
//        	   long extendedQueryStart = System.currentTimeMillis();
1168 1191
               pstmt = dbconn.prepareStatement(extendedQuery);
1169 1192
               //increase dbconnection usage count
1170 1193
               dbconn.increaseUsageCount(1);
1171 1194
               pstmt.execute();
1172 1195
               rs = pstmt.getResultSet();
1173
               double extendedQueryEnd = System.currentTimeMillis() / 1000;
1174
               logMetacat.warn(
1175
                   "Time to execute extended query: "
1176
                   + (extendedQueryEnd - extendedQueryStart));
1177
               MetacatUtil.writeDebugToFile(
1178
                       "Execute extended query "
1179
                       + (extendedQueryEnd - extendedQueryStart));
1180
               MetacatUtil.writeDebugToDelimiteredFile(" "+ (extendedQueryEnd - extendedQueryStart), false);
1196
//               MetacatUtil.writeDebugToDelimiteredFile(" "+ (extendedQueryEnd - extendedQueryStart), false);
1181 1197
               tableHasRows = rs.next();
1182 1198
               while (tableHasRows) {
1183 1199
                   ReturnFieldValue returnValue = new ReturnFieldValue();
......
1260 1276
                         new ResultDocument(docid, object.getXMLFieldValue()));
1261 1277
                   }
1262 1278
               } //while
1263
               double docListResultEnd = System.currentTimeMillis() / 1000;
1264
               logMetacat.warn(
1265
                   "Time to prepare ResultDocumentSet after"
1266
                   + " execute extended query: "
1267
                   + (docListResultEnd - extendedQueryEnd));
1279
//               double docListResultEnd = System.currentTimeMillis() / 1000;
1280
//               logMetacat.warn(
1281
//                   "Time to prepare ResultDocumentSet after"
1282
//                   + " execute extended query: "
1283
//                   + (docListResultEnd - extendedQueryEnd));
1268 1284
           }
1269 1285

  
1270 1286
         
......
1327 1343
	   {
1328 1344
          try
1329 1345
          {
1330
        	 logMetacat.info("Get query from cache ===");
1346
        	 logMetacat.info("DBQuery.getResultXMLFromCache - Get query from cache");
1331 1347
		     resultSet = (String)queryResultCache.get(query);
1332 1348
		   
1333 1349
          }
......
1742 1758
            pStmt.close();
1743 1759
        }//try
1744 1760
        catch (SQLException e) {
1745
            logMetacat.error("Error in getDocidListForDataPackage: "
1761
            logMetacat.error("DBQuery.getCurrentDocidListForDataPackage - Error in getDocidListForDataPackage: "
1746 1762
                    + e.getMessage());
1747 1763
        }//catch
1748 1764
        finally {
......
1750 1766
                pStmt.close();
1751 1767
            }//try
1752 1768
            catch (SQLException ee) {
1753
                logMetacat.error(
1754
                        "Error in getDocidListForDataPackage: "
1769
                logMetacat.error("DBQuery.getCurrentDocidListForDataPackage - SQL Error: "
1755 1770
                                + ee.getMessage());
1756 1771
            }//catch
1757 1772
            finally {
......
1803 1818
            }//for
1804 1819
        }//try
1805 1820
        catch (Exception e) {
1806
            logMetacat.error("Error in getOldVersionAllDocumentImpl: "
1821
            logMetacat.error("DBQuery.getCurrentDocidListForDataPackage - General error: "
1807 1822
                    + e.getMessage());
1808 1823
        }//catch
1809 1824

  
......
1846 1861
            pStmt.close();
1847 1862
        }//try
1848 1863
        catch (SQLException e) {
1849
            logMetacat.error("Error in isDataPackageId: "
1864
            logMetacat.error("DBQuery.isDataPackageId - SQL Error: "
1850 1865
                    + e.getMessage());
1851 1866
        } finally {
1852 1867
            try {
1853 1868
                pStmt.close();
1854 1869
            }//try
1855 1870
            catch (SQLException ee) {
1856
                logMetacat.error("Error in isDataPackageId: "
1871
                logMetacat.error("DBQuery.isDataPackageId - SQL Error in isDataPackageId: "
1857 1872
                        + ee.getMessage());
1858 1873
            }//catch
1859 1874
            finally {
......
1914 1929

  
1915 1930
        }//try
1916 1931
        catch (SQLException e) {
1917
            logMetacat.error(
1918
                    "Error in getCurrentRevFromXMLDoumentsTable: "
1932
            logMetacat.error("DBQuery.getCurrentRevFromXMLDoumentsTable - SQL Error: "
1919 1933
                            + e.getMessage());
1920 1934
            throw e;
1921 1935
        }//catch
......
1925 1939
            }//try
1926 1940
            catch (SQLException ee) {
1927 1941
                logMetacat.error(
1928
                        "Error in getCurrentRevFromXMLDoumentsTable: "
1942
                        "DBQuery.getCurrentRevFromXMLDoumentsTable - SQL Error: "
1929 1943
                                + ee.getMessage());
1930 1944
            }//catch
1931 1945
            finally {
......
2009 2023
                documentImplList.add(documentImplObject);
2010 2024
            }//try
2011 2025
            catch (Exception e) {
2012
                logMetacat.error("Error in getCurrentAllDocumentImpl: "
2026
                logMetacat.error("DBQuery.getCurrentAllDocumentImpl - General error: "
2013 2027
                        + e.getMessage());
2014 2028
                // continue the for loop
2015 2029
                continue;
......
2050 2064
                documentImplList.add(documentImplObject);
2051 2065
            }//try
2052 2066
            catch (McdbDocNotFoundException notFoundE) {
2053
                logMetacat.error(
2054
                        "Error in DBQuery.getOldVersionAllDocument" + "Imple"
2055
                                + notFoundE.getMessage());
2067
                logMetacat.error("DBQuery.getOldVersionAllDocument - Error finding doc " 
2068
                		+ docidPlusVersion + " : " + notFoundE.getMessage());
2056 2069
                // Rather than add a DocumentImple object into vetor, a String
2057 2070
                // object
2058 2071
                // - the doicd was added to the vector
......
2062 2075
            }//catch
2063 2076
            catch (Exception e) {
2064 2077
                logMetacat.error(
2065
                        "Error in DBQuery.getOldVersionAllDocument" + "Imple"
2078
                        "DBQuery.getOldVersionAllDocument - General error: "
2066 2079
                                + e.getMessage());
2067 2080
                // Continue the for loop
2068 2081
                continue;
......
2107 2120
            zipOut.closeEntry();
2108 2121
        }//try
2109 2122
        catch (IOException ioe) {
2110
            logMetacat.error("There is an exception: "
2123
            logMetacat.error("DBQuery.addDataFileToZipOutputStream - I/O error: "
2111 2124
                    + ioe.getMessage());
2112 2125
        }//catch
2113 2126
    }//addDataFileToZipOutputStream()
......
2316 2329
                        .equals("class java.lang.String")) {
2317 2330
                    // Get String object from vetor
2318 2331
                    String documentId = (String) documentImplList.elementAt(i);
2319
                    logMetacat.info("docid: " + documentId);
2332
                    logMetacat.info("DBQuery.getZippedPackage - docid: " + documentId);
2320 2333
                    // Get doicd without revision
2321 2334
                    String docidWithoutRevision = 
2322 2335
                    	DocumentUtil.getDocIdFromString(documentId);
2323
                    logMetacat.info("docidWithoutRevsion: "
2336
                    logMetacat.info("DBQuery.getZippedPackage - docidWithoutRevsion: "
2324 2337
                            + docidWithoutRevision);
2325 2338
                    // Get revision
2326 2339
                    String revision = 
2327 2340
                    	DocumentUtil.getRevisionStringFromString(documentId);
2328
                    logMetacat.info("revsion from docIdentifier: "
2341
                    logMetacat.info("DBQuery.getZippedPackage - revision from docIdentifier: "
2329 2342
                            + revision);
2330 2343
                    // Zip entry string
2331 2344
                    String zipEntryPath = rootName + "/data/";

Also available in: Unified diff