[Building Sakai] production disaster apparently due to chat

[Hedrick Charles]

I see two problems. I've just fixed one, and will be rushing it into production. I haven't fixed the other.

When delivering a chat message, a list of ChatDelivery is created per user session (more or less). ChatDelivery has either a message ID or the actual message. When adding to the list, it checks whether the message is already there. That check uses equals. One thinks of equals as quick. Unfortunatley equals for a ChatDelivery checks whether the underlying messages are equal, as follows:

  this.getMessage.getId() .equals o.getMessage.getId()

The problem is that normally what you have is the message ID, a simple string. This code forces the message itself to be fetched, just to get the ID, which is of course the string that you already had. The solution is to add a new function getMessageId() which if you have the ID just returns it, while if you have the whole message it returns getId() of it.

That should reduce the database I/O occurring in ClusterEventTracking, where of course it's all happening in one thread, serialized. However when delivering to the user it is still going to have to fetch the message itself. But it's going to do a separate fetch per Delivery, i.e. per user in the site. This is unnecessary. You only need to fetch each message once. The ChatDelivery object shouldn't get its own copy of the message (or you should enable the cache in hibernate for this tool). The advantage of my fix is that those fetches are not serialized inside ClusterEventTracking, but we've still got way too much database activity. I need to get a fix up now, so I'm going to do the fix just outlined and worry later about fetching each message just once for delivery.


On Nov 2, 2011, at 7:50:54 PM, Hedrick Charles wrote:

> This evening we had a disaster that appears to be due to chat.
> 
> I found 2 of our 3 front end systems in more or less continuous GC. I also found ClusterEventTracking at 100%. I assume this is not coincidence. The backtrace looked like this. I'm continuing to investigate.
> 
> com.mysql.jdbc.ResultSetImpl.findColumn(ResultSetImpl.java:1106)
> com.mysql.jdbc.ResultSetImpl.getString(ResultSetImpl.java:5617)
> org.apache.commons.dbcp.DelegatingResultSet.getString(DelegatingResultSet.java:225)
> org.hibernate.type.StringType.get(StringType.java:18)
> org.hibernate.type.NullableType.nullSafeGet(NullableType.java:163)
> org.hibernate.type.NullableType.nullSafeGet(NullableType.java:154)
> org.hibernate.loader.Loader.getKeyFromResultSet(Loader.java:1097)
> org.hibernate.loader.Loader.getRowFromResultSet(Loader.java:565)
> org.hibernate.loader.Loader.doQuery(Loader.java:701)
> org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:236)
> org.hibernate.loader.Loader.loadEntity(Loader.java:1864)
> org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:48)
> org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:42)
> org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3039)
> org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:399)
> org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:375)
> org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:139)
> org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:195)
> org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:103)
> org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:879)
> org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:847)
> org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:567)
> org.hibernate.type.EntityType.resolve(EntityType.java:389)
> org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:120)
> org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:854)
> org.hibernate.loader.Loader.doQuery(Loader.java:729)
> org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:236)
> org.hibernate.loader.Loader.loadEntity(Loader.java:1864)
> org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:48)
> org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:42)
> org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3039)
> org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:399)
> org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:375)
> org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:139)
> org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:195)
> org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:103)
> org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:879)
> org.hibernate.impl.SessionImpl.get(SessionImpl.java:816)
> org.hibernate.impl.SessionImpl.get(SessionImpl.java:809)
> org.springframework.orm.hibernate3.HibernateTemplate$1.doInHibernate(HibernateTemplate.java:531)
> org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:419)
> org.springframework.orm.hibernate3.HibernateTemplate.executeWithNativeSession(HibernateTemplate.java:374)
> org.springframework.orm.hibernate3.HibernateTemplate.get(HibernateTemplate.java:525)
> org.springframework.orm.hibernate3.HibernateTemplate.get(HibernateTemplate.java:519)
> org.sakaiproject.chat2.model.impl.ChatManagerImpl.getMessage(ChatManagerImpl.java:563)
> sun.reflect.GeneratedMethodAccessor5759.invoke(Unknown Source)
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> java.lang.reflect.Method.invoke(Method.java:597)
> org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
> org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106)
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
> $Proxy48.getMessage(Unknown Source)
> org.sakaiproject.chat2.tool.ChatDelivery.getMessage(ChatDelivery.java:80)
> org.sakaiproject.chat2.tool.ChatDelivery.equals(ChatDelivery.java:191)
> java.util.ArrayList.indexOf(ArrayList.java:216)
> java.util.ArrayList.contains(ArrayList.java:199)
> org.sakaiproject.courier.impl.BasicCourierService.deliver(BasicCourierService.java:137)
> org.sakaiproject.chat2.tool.ChatTool.receivedMessage(ChatTool.java:393)
> org.sakaiproject.chat2.model.impl.ChatManagerImpl.update(ChatManagerImpl.java:868)
> java.util.Observable.notifyObservers(Observable.java:142)
> org.sakaiproject.event.impl.BaseEventTrackingService.notifyObservers(BaseEventTrackingService.java:120)
> org.sakaiproject.event.impl.ClusterEventTracking.run(ClusterEventTracking.java:682)
> java.lang.Thread.run(Thread.java:662)
> 

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://collab.sakaiproject.org/pipermail/sakai-dev/attachments/20111102/e5c0bf7e/attachment.html