Changeset 7128


Ignore:
Timestamp:
Apr 21, 2016, 9:48:55 AM (5 years ago)
Author:
Nicklas Nordborg
Message:

References #2000: Batch API for annotation handling

Added support for change history logging. The logging is implemented by submitting the CurrentAnnotationInfo instance to the LoggingInterceptor. To make this work the logging system need to be updated to immediately do the logging instead of keeping all changes in a temporary cache.

The existing AnnotationLogger has been updated so that it is able to take care of both the regular logging and the special logging.

Initial tests indicate that the loggin add 2-3 minutes to the total time both when adding and deleting annotations. Adding is now up to 7 minutes and deleting up to 10 minutes. This can probably be reduced by implementing the logging also as a batcher. But this is probably another ticket...

Location:
trunk/src/core/net/sf/basedb/core
Files:
4 edited

Legend:

Unmodified
Added
Removed
  • trunk/src/core/net/sf/basedb/core/AnnotationBatcher.java

    r7127 r7128  
    3838
    3939import net.sf.basedb.core.data.AnnotatableData;
     40import net.sf.basedb.core.data.LoggableData;
     41import net.sf.basedb.core.log.ChangeType;
     42import net.sf.basedb.core.log.LoggingInterceptor;
     43import net.sf.basedb.core.log.db.AnnotationLogger;
    4044import net.sf.basedb.core.snapshot.SnapshotManager;
    4145import net.sf.basedb.util.EqualsHelper;
     
    9599  private final org.hibernate.dialect.Dialect dialect;
    96100  private final org.hibernate.Cache secondLevelCache;
     101
     102  // Log changes directly to the LoggingInterceptor
     103  private final LoggingInterceptor loggingInterceptor;
    97104
    98105  // Discriminator values for Type items (eg. Type.INT -> IntegerParameterValueData -> 1)
     
    160167    @param itemType The type of items to work with. This must be an annotatable item type.
    161168  */
     169  @SuppressWarnings({ "unchecked", "rawtypes" })
    162170  public AnnotationBatcher(DbControl dc, Item itemType)
    163171  {
     
    179187    this.dialect = HibernateUtil.getDialect();
    180188    this.secondLevelCache = HibernateUtil.getSessionFactory().getCache();
     189    // Log changes if the items are implementing the LoggableData interface
     190    this.loggingInterceptor = LoggableData.class.isAssignableFrom(itemType.getDataClass()) ?
     191      dc.getLoggingInterceptor() : null;
    181192
    182193    Type[] types = Type.values();
     
    419430      }
    420431     
    421       CurrentAnnotationInfo info = new CurrentAnnotationInfo(at);
     432      CurrentAnnotationInfo info = new CurrentAnnotationInfo(at, itemType);
    422433      currentInfo.put(at.getId(), info);
    423434    }
     
    465476    this.evictFromSecondLevelCacheIfModified = secondLevelCache != null && secondLevelCache.containsEntity(itemType.getDataClass(), item.getId());
    466477
     478    int itemId = item.getId();
     479    for (CurrentAnnotationInfo info : currentInfo.values())
     480    {
     481      info.itemId = itemId;
     482      info.hasBeenUsed = false;
     483      info.annotationId = null;
     484      info.version = 0;
     485      info.unitId = null;
     486      info.valueId = 0;
     487      info.lastUpdated = null;
     488      info.values.clear();
     489      info.newValues = null;
     490    }
     491   
    467492    // Read current values
    468493    if (item.isAnnotated())
     
    498523        if (isDebugEnabled)
    499524        {
    500           log.trace("Found annotation: AnnotationType.id=" + info.annotationTypeId);
     525          log.trace("Found annotation: AnnotationType=" + info.annotationType);
    501526        }
    502527       
     
    504529        int typeIndex = info.valueType.ordinal();
    505530       
    506         // Reset the current annotation information
    507         info.itemId = item.getId();
    508         info.hasBeenUsed = false;
     531        // Set current annotation information
    509532        info.annotationId = (Integer)data[1];
    510533        info.version = (Integer)data[2];
     
    512535        info.valueId = (Integer)data[4];
    513536        info.lastUpdated = (Date)data[5];
    514         info.values.clear();
    515537       
    516538        valueIds[typeIndex].add(info.valueId);
     
    602624    }
    603625   
    604     boolean infoIsForCurrentItem = info.itemId == currentItem.getId();
    605     if (infoIsForCurrentItem && info.hasBeenUsed)
     626    if (info.hasBeenUsed)
    606627    {
    607628      throw new IllegalStateException("Not allowed to call this method with the same annotation more than once: " + annotationType);
     
    614635   
    615636    info.hasBeenUsed = true;
    616     info.itemId = currentItem.getId();
     637    info.newValues = values;
    617638   
    618639    Change changeType = Change.NO_CHANGE;
     
    621642      if (values == null || values.size() == 0)
    622643      {
    623         if (infoIsForCurrentItem)
     644        if (info.annotationId != null)
    624645        {
    625646          if (isDebugEnabled)
     
    690711          convertedValues.add(value);
    691712        }
     713        info.newValues = convertedValues;
    692714       
    693         if (infoIsForCurrentItem)
     715        if (info.annotationId != null)
    694716        {
    695717          // Update the current annotation if the value(s) have changed
     
    762784
    763785          // Insert into Annotations
    764           info.annotationId = insertIntoAnnotations.insert(currentAnnotationSetId, info.annotationTypeId, info.unitId, info.valueId, batchDate);
     786          info.annotationId = insertIntoAnnotations.insert(currentAnnotationSetId, annotationType.getId(), info.unitId, info.valueId, batchDate);
    765787        }
    766788      }
     
    781803        snapshotsToDelete.add(currentAnnotationSetId);
    782804      }
     805      if (loggingInterceptor != null)
     806      {
     807        loggingInterceptor.addManualSingleChange(changeType.getLogChangeType(), info);
     808      }
    783809    }
    784810   
     
    796822      The annotation was not changed.
    797823    */
    798     NO_CHANGE,
     824    NO_CHANGE(null),
    799825   
    800826    /**
    801827      A new annotation was created.
    802828    */
    803     ADDED,
     829    ADDED(ChangeType.ADD),
    804830   
    805831    /**
    806832      An existing annotation was updated.
    807833    */
    808     UPDATED,
     834    UPDATED(ChangeType.UPDATE),
    809835   
    810836    /**
    811837      An existing annotation was deleted.
    812838    */
    813     DELETED;
    814    
     839    DELETED(ChangeType.REMOVE);
     840   
     841    private final ChangeType logChangeType;
     842   
     843    Change(ChangeType logChangeType)
     844    {
     845      this.logChangeType = logChangeType;
     846    }
     847   
     848    ChangeType getLogChangeType()
     849    {
     850      return logChangeType;
     851    }
    815852  }
    816853 
     
    825862    The 'hasBeenUsed' flag is set to prevent calling the setValues() method
    826863    more than once for each annotation type.
    827   */
    828   static class CurrentAnnotationInfo
     864   
     865    This class exposes some information publicly since it is used for
     866    change history logging. See {@link AnnotationLogger}.
     867  */
     868  public static class CurrentAnnotationInfo
     869    implements LoggableData
    829870  {
    830871    // Pre-initialized
    831     final int annotationTypeId;
     872    final AnnotationType annotationType;
    832873    final Type valueType;
    833874    final Unit defaultUnit;
     875    final Item itemType;
    834876   
    835877    // Updated in setCurrentItem
    836878    int itemId;
    837879    boolean hasBeenUsed;
    838     int annotationId;
     880    Integer annotationId;
    839881    int version;
    840882    Integer unitId;
     
    842884    Date lastUpdated;
    843885    final List<Object> values;
    844    
    845     CurrentAnnotationInfo(AnnotationType at)
    846     {
    847       this.annotationTypeId = at.getId();
     886    List<?> newValues;
     887   
     888    CurrentAnnotationInfo(AnnotationType at, Item itemType)
     889    {
     890      this.annotationType = at;
     891      this.itemType = itemType;
    848892      this.valueType = at.getValueType();
    849893      this.defaultUnit = at.getDefaultUnit();
    850894      this.values = new ArrayList<Object>();
     895    }
     896   
     897    /**
     898      Get the annotation type.
     899    */
     900    public AnnotationType getAnnotationType()
     901    {
     902      return annotationType;
     903    }
     904   
     905    /**
     906      Shortcut to {@link AnnotationType#getValueType()}.
     907    */
     908    public Type getValueType()
     909    {
     910      return valueType;
     911    }
     912   
     913    /**
     914      Get the default unit for the annotation type.
     915      @see AnnotationType#getDefaultUnit()
     916    */
     917    public Unit getDefaultUnit()
     918    {
     919      return defaultUnit;
     920    }
     921   
     922    /**
     923      Get the item type of the item.
     924    */
     925    public Item getItemType()
     926    {
     927      return itemType;
     928    }
     929   
     930    /**
     931      Get the id of the current item.
     932    */
     933    public int getItemId()
     934    {
     935      return itemId;
     936    }
     937   
     938    /**
     939      Get the ID of the unit this annotation is using.
     940    */
     941    public Integer getUnitId()
     942    {
     943      return unitId;
     944    }
     945   
     946    /**
     947      Get the old annotation values. If the annotation
     948      uses units, the values are always in the default unit
     949      specified by the annotation type.
     950    */
     951    public List<?> getOldValues()
     952    {
     953      return values;
     954    }
     955   
     956    /**
     957      Get the new annotation values. If the annotation
     958      uses units, the values are always in the default unit
     959      specified by the annotation type.
     960    */
     961    public List<?> getNewValues()
     962    {
     963      return newValues;
    851964    }
    852965  }
  • trunk/src/core/net/sf/basedb/core/log/LoggingInterceptor.java

    r7075 r7128  
    6969
    7070  private static final long serialVersionUID = -9108587050205509572L;
     71 
     72  // Empty arrays to use when there is no other information
     73  private static final Object[] EMTPY_OBJECT_ARRAY = new Object[0];
     74  private static final String[] EMTPY_STRING_ARRAY = new String[0];
     75  private static final Type[] EMTPY_TYPE_ARRAY = new Type[0];
     76 
    7177  private final LogControl logControl;
    7278  private final ExtensionsInvoker<LogManagerFactory> logInvoker;
     
    97103      String[] propertyNames, Type[] types)
    98104  {
    99     addChange(ChangeType.CREATE, entity, state, null, propertyNames, types);
     105    addChange(ChangeType.CREATE, entity, state, null, propertyNames, types, false);
    100106    return false;
    101107  }
     
    110116      Type[] types)
    111117  {
    112     addChange(ChangeType.UPDATE, entity, currentState, previousState, propertyNames, types);
     118    addChange(ChangeType.UPDATE, entity, currentState, previousState, propertyNames, types, false);
    113119    return false;
    114120  }
     
    121127      String[] propertyNames, Type[] types)
    122128  {
    123     addChange(ChangeType.DELETE, entity, state, state, propertyNames, types);
     129    addChange(ChangeType.DELETE, entity, state, state, propertyNames, types, false);
    124130  }
    125131
     
    178184
    179185  /**
    180     Adds a manual non-Hibernate change to the log system.
     186    Adds a manual non-Hibernate change to the log system. The change is
     187    forwarded to the log handlers immediately. The
     188    log handlers should not store the entity object for later use since
     189    instance may be reused for other changes in the future.
    181190    @since 3.3
    182191  */
    183192  public void addManualSingleChange(ChangeType action, Object entity, Object newValue, Object oldValue, String property, Type type)
    184193  {
    185     addChange(action, entity, new Object[] { newValue }, new Object[] { oldValue }, new String[] { property }, new Type[] { type });
     194    addChange(action, entity, new Object[] { newValue }, new Object[] { oldValue }, new String[] { property }, new Type[] { type }, true);
     195  }
     196 
     197  /**
     198    Adds a manual non-Hibernate change to the log system. The entity should be
     199    a special object that doesn't rely on the state arrays to convey what has
     200    changed. The change is forwarded to the log handlers immediately. The
     201    log handlers should not store the entity object for later use since
     202    instance may be reused for other changes in the future.
     203    @since 3.8
     204  */
     205  public void addManualSingleChange(ChangeType action, Object entity)
     206  {
     207    addChange(action, entity, EMTPY_OBJECT_ARRAY, EMTPY_OBJECT_ARRAY, EMTPY_STRING_ARRAY, EMTPY_TYPE_ARRAY, true);
    186208  }
    187209 
     
    192214   */
    193215  private void addChange(ChangeType action, Object entity, Object[] state,
    194       Object[] previousState, String[] propertyNames, Type[] types)
     216      Object[] previousState, String[] propertyNames, Type[] types, boolean logImmediately)
    195217  {
    196218    if (logHandlers == null)
     
    215237        if (details == null) details = new EntityDetails(entity, action,
    216238            state, previousState, propertyNames, types);
    217         changes.add(new LogDetails(handler.manager, logger, details));
     239        if (logImmediately)
     240        {
     241          logger.logChanges(handler.manager, details); 
     242        }
     243        else
     244        {
     245          changes.add(new LogDetails(handler.manager, logger, details));
     246        }
    218247      }
    219248    }
  • trunk/src/core/net/sf/basedb/core/log/db/AnnotationLogger.java

    r6981 r7128  
    2222package net.sf.basedb.core.log.db;
    2323
     24import java.util.List;
     25
    2426import org.hibernate.Hibernate;
    2527import org.hibernate.Query;
    2628
    2729import net.sf.basedb.core.Annotation;
     30import net.sf.basedb.core.AnnotationBatcher.CurrentAnnotationInfo;
     31import net.sf.basedb.core.AnnotationType;
    2832import net.sf.basedb.core.Item;
    2933import net.sf.basedb.core.LogControl;
     
    7175  {
    7276    LogControl logControl = logManager.getLogControl();
    73     AnnotationData annotation = (AnnotationData)details.getEntity();
    74    
    75     // Get the name of the annotation type
     77   
     78    Object entity = details.getEntity();
    7679    String annotationType = null;
    7780    Type valueType = null;
    78     boolean disableLogOfValues = false;
    79     AnnotationTypeData at = annotation.getAnnotationType();
    80     if (!Hibernate.isInitialized(at))
    81     {
     81    boolean logOldPropertyValues = factory.isLoggingOldPropertyValues();
     82    Integer parentId = null;
     83    Integer parentType = null;
     84    Annotation.Source source = null;
     85    List<?> newValues = null;
     86    List<?> oldValues = null;
     87
     88    if (entity instanceof CurrentAnnotationInfo)
     89    {
     90      // Log entry from AnnotationBatcher
     91      CurrentAnnotationInfo info = (CurrentAnnotationInfo)entity;
     92      AnnotationType at = info.getAnnotationType();
     93      annotationType = at.getName();
     94      valueType = info.getValueType();
     95     
     96      parentId = info.getItemId();
     97      parentType = info.getItemType().getValue();
     98     
     99      source = Annotation.Source.PRIMARY;
     100      oldValues = info.getOldValues();
     101      newValues = info.getNewValues();
     102    }
     103    else if (entity instanceof AnnotationData)
     104    {
     105      // Regular log entry via Hibernate
     106      AnnotationData annotation = (AnnotationData)entity;
     107      AnnotationTypeData at = annotation.getAnnotationType();
     108      if (!Hibernate.isInitialized(at))
     109      {
     110        Query q = logControl.createHqlQuery(
     111            PredefinedQuery.getQueryString("DBLOG_GET_ANNOTATIONTYPE_INFO"));
     112        q.setInteger("annotationTypeId", at.getId());
     113        Object[] tmp = (Object[])q.uniqueResult();
     114        annotationType = (String)tmp[0];
     115        valueType = Type.fromValue((Integer)tmp[1]);
     116        if ((Boolean)tmp[2]) logOldPropertyValues = false;
     117      }
     118      else
     119      {
     120        annotationType = at.getName();
     121        valueType = Type.fromValue(at.getValueType());
     122        if (at.getDisableLogOfValues()) logOldPropertyValues = false;
     123      }
     124     
     125      // Get the type of the parent item
     126      AnnotationSetData as = annotation.getAnnotationSet();
     127      if (!Hibernate.isInitialized(as))
     128      {
     129        Query q = logControl.createHqlQuery(
     130          PredefinedQuery.getQueryString("DBLOG_GET_ANNOTATION_ITEMTYPE"));
     131        q.setInteger("annotationSetId", as.getId());
     132        parentType = (Integer)q.uniqueResult();     
     133      }
     134      else
     135      {
     136        parentType = as.getItemType();
     137      }
     138     
     139      // May happen in case the annotation set has been deleted in this transaction
     140      if (parentType == null) return;
     141     
     142      Class<?> parentClass = Item.fromValue(parentType).getDataClass();
     143      // If the parent item isn't implementing the LoggableData interface
     144      // we don't log the changes
     145      if (!LoggableData.class.isAssignableFrom(parentClass)) return;
     146
     147      // Get the id of the parent item
    82148      Query q = logControl.createHqlQuery(
    83           PredefinedQuery.getQueryString("DBLOG_GET_ANNOTATIONTYPE_INFO"));
    84       q.setInteger("annotationTypeId", at.getId());
    85       Object[] tmp = (Object[])q.uniqueResult();
    86       annotationType = (String)tmp[0];
    87       valueType = Type.fromValue((Integer)tmp[1]);
    88       disableLogOfValues = (Boolean)tmp[2];
    89     }
    90     else
    91     {
    92       annotationType = at.getName();
    93       valueType = Type.fromValue(at.getValueType());
    94       disableLogOfValues = at.getDisableLogOfValues();
    95     }
    96    
    97     // Get the type of the parent item
    98     AnnotationSetData as = annotation.getAnnotationSet();
    99     Integer parentType = null;
    100     if (!Hibernate.isInitialized(as))
    101     {
    102       Query q = logControl.createHqlQuery(
    103         PredefinedQuery.getQueryString("DBLOG_GET_ANNOTATION_ITEMTYPE"));
     149        PredefinedQuery.getQueryString("DBLOG_GET_ITEMID_WITH_ANNOTATION", parentClass.getName()));
    104150      q.setInteger("annotationSetId", as.getId());
    105       parentType = (Integer)q.uniqueResult();     
    106     }
    107     else
    108     {
    109       parentType = as.getItemType();
    110     }
    111    
    112     // May happen in case the annotation set has been deleted in this transaction
    113     if (parentType == null) return;
    114    
    115     Class<?> parentClass = Item.fromValue(parentType).getDataClass();
    116     // If the parent item isn't implementing the LoggableData interface
    117     // we don't log the changes
    118     if (!LoggableData.class.isAssignableFrom(parentClass)) return;
    119    
    120     // Get the id of the parent item
    121     Query q = logControl.createHqlQuery(
    122       PredefinedQuery.getQueryString("DBLOG_GET_ITEMID_WITH_ANNOTATION", parentClass.getName()));
    123     q.setInteger("annotationSetId", as.getId());
    124     Integer parentId = (Integer)q.uniqueResult();
    125    
    126     // May happen in case the parent item has been deleted in this transaction
    127     if (parentId == null) return;
     151      parentId = (Integer)q.uniqueResult();
     152     
     153      // May happen in case the parent item has been deleted in this transaction
     154      if (parentId == null) return;
     155   
     156      source = Annotation.Source.values()[annotation.getSource()];
     157      if (logOldPropertyValues)
     158      {
     159        ParameterValueData<?> values = annotation.getValues();
     160        if (values != null)
     161        {
     162          newValues = values.getValues();
     163          oldValues = values.getOldValues();
     164        }
     165        else
     166        {
     167          logOldPropertyValues = false;
     168        }
     169      }
     170    }
    128171   
    129172    ChangeType changeType = details.getChangeType();
     
    141184    change.setItemId(parentId);
    142185    change.setItemType(parentType);
    143     Annotation.Source source = Annotation.Source.values()[annotation.getSource()];
     186
    144187    if (source == Annotation.Source.CLONED)
    145188    {
     
    154197      change.setChangeInfo("Annotation["+annotationType+"]");
    155198    }
    156     if (factory.isLoggingOldPropertyValues() && !disableLogOfValues)
     199    if (logOldPropertyValues)
    157200    {
    158201      Formatter f = null;
     
    165208        f = EntityDetails.DATETIME_FORMAT;
    166209      }
    167       ParameterValueData<?> values = annotation.getValues();
    168       if (values != null)
    169       {
    170         String newValues = Values.getString(values.getValues(), ", ", true, f);
    171         String oldValues = Values.getString(values.getOldValues(), ", ", true, f);
    172         change.setNewValue(newValues.length() == 0 ? null : newValues);
    173         change.setOldValue(oldValues.length() == 0 ? null : oldValues);
    174       }
     210     
     211      String sNew = Values.getString(newValues, ", ", true, f);
     212      String sOld = Values.getString(oldValues, ", ", true, f);
     213      change.setNewValue(sNew.length() == 0 ? null : sNew);
     214      change.setOldValue(sOld.length() == 0 ? null : sOld);
    175215    }
    176216    ((DbLogManager)logManager).logChangeDetails(change, details);
  • trunk/src/core/net/sf/basedb/core/log/db/DbLogManagerFactory.java

    r6875 r7128  
    2525import java.util.Map;
    2626
     27import net.sf.basedb.core.AnnotationBatcher.CurrentAnnotationInfo;
    2728import net.sf.basedb.core.Config;
    2829import net.sf.basedb.core.LogControl;
     
    7980    setSpecialLogger(BioMaterialEventData.class, new BioMaterialEventLogger(this));
    8081    setSpecialLogger(AnnotationData.class, new AnnotationLogger(this));
     82    setSpecialLogger(CurrentAnnotationInfo.class, new AnnotationLogger(this));
    8183    setSpecialLogger(FileSetMemberData.class, new FileSetMemberLogger(this));
    8284    setSpecialLogger(PlateEventData.class, new PlateEventLogger(this));
     
    155157      at the same time
    156158  */
    157   public void setSpecialLogger(Class<?> clazz, EntityLogger logger)
     159  public void setSpecialLogger(Class<? extends LoggableData> clazz, EntityLogger logger)
    158160  {
    159161    if (clazz == null) throw new NullPointerException("clazz");
Note: See TracChangeset for help on using the changeset viewer.