How can I determine the cause of an extremely large SQL transaction log file?

[Koos]

We are running a quite small JIRA Server installation on Microsoft Server 2008 r2 with Microsoft SQL Server 2008 database connected and 10 users.

The database size is only 20 Mb or so, but the transaction log is currenly 11 Gb, which is quite unsettling.

The transaction log keeps growing, despite the fact that backups are all running correctly and set up correctly according to our IT department.

I can find some discussion on similar issues regarding large transaction logs, also with regards to open transactions.

Can somebody help determining the cause of the extraordinary large transaction log file? I turned on the SQL logging in JIRA for a couple of minutes, which created a log file of over 1 Mb containing a lot of error messages. Could the database somehow be corrupt? Below a short snippet of the SQL log (atlassian-jira-sql-log).

------------------------

2017-08-21 10:41:37,103 http-nio-80-exec-12 admin 641x11048x1 18ueb4d /secure/admin/ViewLogging.jspa 0ms Connection taken. borrowed : 4
2017-08-21 10:41:37,119 http-nio-80-exec-12 admin 641x11048x1 18ueb4d /secure/admin/ViewLogging.jspa 16ms "SELECT ID, filename, contenttype, avatartype, owner, systemavatar FROM dbo.avatar WHERE filename='Avatar-default.svg' AND avatartype='user' AND systemavatar='1'"
2017-08-21 10:41:37,119 http-nio-80-exec-12 admin 641x11048x1 18ueb4d /secure/admin/ViewLogging.jspa call stack
...
at com.atlassian.jira.avatar.CachingTaggingAvatarStore.getAvatars(CachingTaggingAvatarStore.java:176)
at com.atlassian.jira.avatar.CachingTaggingAvatarStore.getSystemAvatarsForFilename(CachingTaggingAvatarStore.java:172)
at com.atlassian.jira.avatar.AvatarManagerImpl.loadDefaultAvatarId(AvatarManagerImpl.java:499)
at com.atlassian.jira.avatar.AvatarManagerImpl.lambda$getDefaultAvatarId$481(AvatarManagerImpl.java:520)
at com.atlassian.vcache.internal.core.DefaultRequestCache.lambda$get$18(DefaultRequestCache.java:43)
at java.util.HashMap.computeIfAbsent(Unknown Source)
at com.atlassian.vcache.internal.core.DefaultRequestCache.get(DefaultRequestCache.java:43)
at com.atlassian.jira.avatar.AvatarManagerImpl.getDefaultAvatarId(AvatarManagerImpl.java:520)
at com.atlassian.jira.avatar.AvatarManagerImpl.getDefaultAvatar(AvatarManagerImpl.java:527)
at sun.reflect.GeneratedMethodAccessor416.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at com.atlassian.plugin.util.ContextClassLoaderSettingInvocationHandler.invoke(ContextClassLoaderSettingInvocationHandler.java:26)
at com.sun.proxy.$Proxy407.getDefaultAvatar(Unknown Source)
at sun.reflect.GeneratedMethodAccessor416.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at org.eclipse.gemini.blueprint.service.importer.support.internal.aop.ServiceInvoker.doInvoke(ServiceInvoker.java:56)
at org.eclipse.gemini.blueprint.service.importer.support.internal.aop.ServiceInvoker.invoke(ServiceInvoker.java:60)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:133)
at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:121)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.eclipse.gemini.blueprint.service.util.internal.aop.ServiceTCCLInterceptor.invokeUnprivileged(ServiceTCCLInterceptor.java:70)
at org.eclipse.gemini.blueprint.service.util.internal.aop.ServiceTCCLInterceptor.invoke(ServiceTCCLInterceptor.java:53)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.eclipse.gemini.blueprint.service.importer.support.LocalBundleContextAdvice.invoke(LocalBundleContextAdvice.java:57)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:133)
at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:121)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)
at com.sun.proxy.$Proxy582.getDefaultAvatar(Unknown Source)
at com.atlassian.jira.avatar.plugin.JiraUserAvatarProvider.getDefaultAvatar(JiraUserAvatarProvider.java:276)
at com.atlassian.jira.avatar.plugin.JiraUserAvatarProvider.getAvatarImpl(JiraUserAvatarProvider.java:228)
at com.atlassian.jira.avatar.plugin.JiraUserAvatarProvider$JiraUserPluginAvatar.<init>(JiraUserAvatarProvider.java:352)
at com.atlassian.jira.avatar.plugin.JiraUserAvatarProvider.getAvatar(JiraUserAvatarProvider.java:155)
at com.atlassian.jira.avatar.pluggable.AvatarProviderAdapter.getAvatar(AvatarProviderAdapter.java:45)
at com.atlassian.jira.avatar.AvatarServiceImpl.getAvatarURLImpl(AvatarServiceImpl.java:209)
at com.atlassian.jira.avatar.AvatarServiceImpl.getAvatarAbsoluteURL(AvatarServiceImpl.java:261)
at com.softwareplant.util.contextint.jiraserver.JiraPrincipalService.convertUser(JiraPrincipalService.java:196)
at com.softwareplant.util.contextint.jiraserver.JiraPrincipalService.getUserByUniqueKey(JiraPrincipalService.java:141)
at com.softwareplant.util.context.permission.PluginPermissionService.hasAccessPermissionToPlugin(PluginPermissionService.java:48)
at com.softwareplant.ppm.structureint.jiraserver.ui.menu.UserPermissionCondition.shouldDisplay(UserPermissionCondition.java:24)
at com.atlassian.jira.plugin.webfragment.conditions.AbstractWebCondition.lambda$shouldDisplay$14(AbstractWebCondition.java:32)
at com.atlassian.ozymandias.SafePluginPointAccess.call(SafePluginPointAccess.java:187)
at com.atlassian.jira.plugin.webfragment.conditions.AbstractWebCondition.shouldDisplay(AbstractWebCondition.java:32)
at com.atlassian.plugin.web.DefaultWebInterfaceManager.filterFragmentsByCondition(DefaultWebInterfaceManager.java:154)
at com.atlassian.plugin.web.DefaultWebInterfaceManager.getDisplayableItems(DefaultWebInterfaceManager.java:107)
at com.atlassian.plugin.web.DefaultWebInterfaceManager.getDisplayableWebItems(DefaultWebInterfaceManager.java:215)
at com.atlassian.jira.plugin.webfragment.DefaultSimpleLinkManager.getLinksForSection(DefaultSimpleLinkManager.java:120)
at com.atlassian.jira.plugin.webfragment.ThreadLocalCachingSimpleLinkManager.access$701(ThreadLocalCachingSimpleLinkManager.java:28)
at com.atlassian.jira.plugin.webfragment.ThreadLocalCachingSimpleLinkManager$3.load(ThreadLocalCachingSimpleLinkManager.java:149)
at com.atlassian.jira.plugin.webfragment.ThreadLocalCachingSimpleLinkManager$3.load(ThreadLocalCachingSimpleLinkManager.java:146)
at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3527)
at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2319)
at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2282)
at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2197)
at com.google.common.cache.LocalCache.get(LocalCache.java:3937)
at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3941)
at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4824)
at com.google.common.cache.LocalCache$LocalLoadingCache.getUnchecked(LocalCache.java:4830)
at com.atlassian.jira.plugin.webfragment.ThreadLocalCachingSimpleLinkManager.getLinksForSection(ThreadLocalCachingSimpleLinkManager.java:153)
at com.atlassian.jira.plugin.webfragment.ThreadLocalCachingSimpleLinkManager.getLinksForSection(ThreadLocalCachingSimpleLinkManager.java:140)
at sun.reflect.GeneratedMethodAccessor347.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at com.atlassian.plugin.util.ContextClassLoaderSettingInvocationHandler.invoke(ContextClassLoaderSettingInvocationHandler.java:26)
at com.sun.proxy.$Proxy534.getLinksForSection(Unknown Source)
at sun.reflect.GeneratedMethodAccessor347.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at org.eclipse.gemini.blueprint.service.importer.support.internal.aop.ServiceInvoker.doInvoke(ServiceInvoker.java:56)
at org.eclipse.gemini.blueprint.service.importer.support.internal.aop.ServiceInvoker.invoke(ServiceInvoker.java:60)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:133)
at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:121)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.eclipse.gemini.blueprint.service.util.internal.aop.ServiceTCCLInterceptor.invokeUnprivileged(ServiceTCCLInterceptor.java:70)
at org.eclipse.gemini.blueprint.service.util.internal.aop.ServiceTCCLInterceptor.invoke(ServiceTCCLInterceptor.java:53)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.eclipse.gemini.blueprint.service.importer.support.LocalBundleContextAdvice.invoke(LocalBundleContextAdvice.java:57)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:133)
at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:121)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)
at com.sun.proxy.$Proxy1390.getLinksForSection(Unknown Source)
at com.atlassian.jira.plugin.headernav.MainHeaderLinksContextProvider.getContextMap(MainHeaderLinksContextProvider.java:71)
at com.atlassian.plugin.web.descriptors.DefaultWebPanelModuleDescriptor$ContextAwareWebPanel.getHtml(DefaultWebPanelModuleDescriptor.java:144)
at com.atlassian.jira.plugin.headernav.ModernPluggableTopNavigation.getHtml(ModernPluggableTopNavigation.java:49)
at com.atlassian.jira.plugin.navigation.HeaderFooterRendering$7.visit(HeaderFooterRendering.java:334)
at com.atlassian.jira.plugin.navigation.HeaderFooterRendering$7.visit(HeaderFooterRendering.java:326)
at com.atlassian.ozymandias.SafePluginPointAccess.invokeModule(SafePluginPointAccess.java:452)
at com.atlassian.ozymandias.SafePluginPointAccess.descriptors(SafePluginPointAccess.java:150)
at com.atlassian.jira.plugin.navigation.HeaderFooterRendering.includeTopNavigation(HeaderFooterRendering.java:326)
at com.atlassian.jira.plugin.navigation.HeaderFooterRendering$1.run(HeaderFooterRendering.java:142)
at com.atlassian.ozymandias.SafePluginPointAccess.runnable(SafePluginPointAccess.java:201)
at com.atlassian.jira.plugin.navigation.HeaderFooterRendering.includeTopNavigation(HeaderFooterRendering.java:139)
at jsp.decorators.admin_jsp._jspService(admin_jsp.java:364)
at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:292)
...

2017-08-21 10:41:37,119 http-nio-80-exec-12 admin 641x11048x1 18ueb4d /secure/admin/ViewLogging.jspa 16ms Connection returned. borrowed : 3
2017-08-21 10:41:37,836 http-nio-80-exec-17 admin 641x11054x3 18ueb4d /rest/hipchat/integrations/1.0/configuration/status 0ms Connection taken. borrowed : 4
2017-08-21 10:41:37,836 http-nio-80-exec-17 admin 641x11054x3 18ueb4d /rest/hipchat/integrations/1.0/configuration/status 0ms Connection returned. borrowed : 3
2017-08-21 10:41:37,836 http-nio-80-exec-19 admin 641x11055x4 18ueb4d /rest/supportHealthCheck/1.0/check/admin 0ms Connection taken. borrowed : 4
2017-08-21 10:41:37,836 http-nio-80-exec-19 admin 641x11055x4 18ueb4d /rest/supportHealthCheck/1.0/check/admin 0ms Connection returned. borrowed : 3
2017-08-21 10:41:37,836 http-nio-80-exec-19 admin 641x11055x4 18ueb4d /rest/supportHealthCheck/1.0/check/admin 0ms Connection taken. borrowed : 4
2017-08-21 10:41:37,836 http-nio-80-exec-19 admin 641x11055x4 18ueb4d /rest/supportHealthCheck/1.0/check/admin 0ms Connection returned. borrowed : 3
2017-08-21 10:41:37,836 http-nio-80-exec-19 admin 641x11055x4 18ueb4d /rest/supportHealthCheck/1.0/check/admin 0ms Connection taken. borrowed : 4
2017-08-21 10:41:37,836 http-nio-80-exec-19 admin 641x11055x4 18ueb4d /rest/supportHealthCheck/1.0/check/admin 0ms Connection returned. borrowed : 3
2017-08-21 10:41:45,231 Caesium-1-4 ServiceRunner 0ms Connection taken. borrowed : 4
2017-08-21 10:41:45,231 Caesium-1-2 ServiceRunner 0ms Connection taken. borrowed : 5
2017-08-21 10:41:45,231 Caesium-1-1 ServiceRunner 0ms Connection taken. borrowed : 6
2017-08-21 10:41:45,231 Caesium-1-3 ServiceRunner 0ms Connection taken. borrowed : 7
2017-08-21 10:41:45,231 Caesium-1-4 ServiceRunner 0ms "SELECT ID, JOB_ID, JOB_RUNNER_KEY, SCHED_TYPE, INTERVAL_MILLIS, FIRST_RUN, CRON_EXPRESSION, TIME_ZONE, NEXT_RUN, VERSION, PARAMETERS FROM dbo.clusteredjob WHERE JOB_ID='61628759-684a-47e4-9ecf-2fcdf9bef63c'"
2017-08-21 10:41:45,231 Caesium-1-4 ServiceRunner call stack
...
at com.atlassian.jira.entity.SelectQueryImpl$ExecutionContextImpl.forEach(SelectQueryImpl.java:227)
at com.atlassian.jira.entity.SelectQueryImpl$ExecutionContextImpl.consumeWith(SelectQueryImpl.java:214)
at com.atlassian.jira.entity.SelectQueryImpl$ExecutionContextImpl.singleValue(SelectQueryImpl.java:191)
at com.atlassian.jira.scheduler.OfBizClusteredJobDao.find(OfBizClusteredJobDao.java:88)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.executeClusteredJob(CaesiumSchedulerService.java:375)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.executeQueuedJob(CaesiumSchedulerService.java:349)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService$1.consume(CaesiumSchedulerService.java:255)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService$1.consume(CaesiumSchedulerService.java:252)
at com.atlassian.scheduler.caesium.impl.SchedulerQueueWorker.executeJob(SchedulerQueueWorker.java:65)
at com.atlassian.scheduler.caesium.impl.SchedulerQueueWorker.executeNextJob(SchedulerQueueWorker.java:59)
at com.atlassian.scheduler.caesium.impl.SchedulerQueueWorker.run(SchedulerQueueWorker.java:34)
at java.lang.Thread.run(Unknown Source)

2017-08-21 10:41:45,231 Caesium-1-4 ServiceRunner 0ms Connection returned. borrowed : 6
2017-08-21 10:41:45,231 Caesium-1-4 ServiceRunner 0ms Connection taken. borrowed : 7
2017-08-21 10:41:45,231 Caesium-1-2 ServiceRunner 0ms "SELECT ID, JOB_ID, JOB_RUNNER_KEY, SCHED_TYPE, INTERVAL_MILLIS, FIRST_RUN, CRON_EXPRESSION, TIME_ZONE, NEXT_RUN, VERSION, PARAMETERS FROM dbo.clusteredjob WHERE JOB_ID='75b6fc1e-cc48-4a85-867a-765ed385f225'"
2017-08-21 10:41:45,231 Caesium-1-2 ServiceRunner call stack
...
at com.atlassian.jira.entity.SelectQueryImpl$ExecutionContextImpl.forEach(SelectQueryImpl.java:227)
at com.atlassian.jira.entity.SelectQueryImpl$ExecutionContextImpl.consumeWith(SelectQueryImpl.java:214)
at com.atlassian.jira.entity.SelectQueryImpl$ExecutionContextImpl.singleValue(SelectQueryImpl.java:191)
at com.atlassian.jira.scheduler.OfBizClusteredJobDao.find(OfBizClusteredJobDao.java:88)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.executeClusteredJob(CaesiumSchedulerService.java:375)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.executeQueuedJob(CaesiumSchedulerService.java:349)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService$1.consume(CaesiumSchedulerService.java:255)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService$1.consume(CaesiumSchedulerService.java:252)
at com.atlassian.scheduler.caesium.impl.SchedulerQueueWorker.executeJob(SchedulerQueueWorker.java:65)
at com.atlassian.scheduler.caesium.impl.SchedulerQueueWorker.executeNextJob(SchedulerQueueWorker.java:59)
at com.atlassian.scheduler.caesium.impl.SchedulerQueueWorker.run(SchedulerQueueWorker.java:34)
at java.lang.Thread.run(Unknown Source)

2017-08-21 10:41:45,231 Caesium-1-2 ServiceRunner 0ms Connection returned. borrowed : 6
2017-08-21 10:41:45,231 Caesium-1-2 ServiceRunner 0ms Connection taken. borrowed : 7
2017-08-21 10:41:45,231 Caesium-1-1 ServiceRunner 0ms "SELECT ID, JOB_ID, JOB_RUNNER_KEY, SCHED_TYPE, INTERVAL_MILLIS, FIRST_RUN, CRON_EXPRESSION, TIME_ZONE, NEXT_RUN, VERSION, PARAMETERS FROM dbo.clusteredjob WHERE JOB_ID='7af98164-99a3-4f3c-bd87-64198775f132'"
2017-08-21 10:41:45,231 Caesium-1-1 ServiceRunner call stack
...
at com.atlassian.jira.entity.SelectQueryImpl$ExecutionContextImpl.forEach(SelectQueryImpl.java:227)
at com.atlassian.jira.entity.SelectQueryImpl$ExecutionContextImpl.consumeWith(SelectQueryImpl.java:214)
at com.atlassian.jira.entity.SelectQueryImpl$ExecutionContextImpl.singleValue(SelectQueryImpl.java:191)
at com.atlassian.jira.scheduler.OfBizClusteredJobDao.find(OfBizClusteredJobDao.java:88)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.executeClusteredJob(CaesiumSchedulerService.java:375)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.executeQueuedJob(CaesiumSchedulerService.java:349)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService$1.consume(CaesiumSchedulerService.java:255)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService$1.consume(CaesiumSchedulerService.java:252)
at com.atlassian.scheduler.caesium.impl.SchedulerQueueWorker.executeJob(SchedulerQueueWorker.java:65)
at com.atlassian.scheduler.caesium.impl.SchedulerQueueWorker.executeNextJob(SchedulerQueueWorker.java:59)
at com.atlassian.scheduler.caesium.impl.SchedulerQueueWorker.run(SchedulerQueueWorker.java:34)
at java.lang.Thread.run(Unknown Source)

-----------------------------------

Any input is appreciated!

[Aron Gombas _Midori_]

From the stacktrace, one can see that this is the "BigGantt" add-on (by SoftwarePlant) that is trying to load user avatars.

If I were you, I'd:

1. First turn off that add-on to verify if that makes the problem go away

2. Contact the developers and tell about my problem

[Koos]

Thanks for your response.

I think that is unlikely, since this problem has been slumbering for a couple of weeks now, and I only installed BigPicture (add-on by SoftwarePlant) last week. It may cause some errors, but I don't think it is the cause of the growing database transaction log file in this case.

[Nic Brough -Adaptavist-]

The first thing that springs to mind is to ask why you're logging the transactions?   You generally don't need them unless you're debugging something. 

The second is that if you do have a good reason for keeping them, then why is there no "log rotation" in place?

[Koos]

The transaction log is part of the full recovery backup system that is in place. By keeping a log of the transactions the database can be restored to a specific point in time. I think this is quite common for backing up of databases.

The log rotation should work by making a backup of the log file. Making the backup should trigger freeing up unused space in the log file.

For now our IT department decided to change the backup mode to 'simple', shrink the transaction log and restore the backup mode to full in order to reclaim disk space. I'm not sure if this will work for the long term though.

[Nic Brough -Adaptavist-]

It is a common approach, but it goes hand-in-hand with log rotation, or you lose disk space.