Execution Slowing on iterative generation of PDF's

[lameid]

My Team generates PDF's in bulk. Fundamentally we have code that does things but at the core loops over recipients, constructs appropriate queries for the data, sets those in Tempvars which reports subsequently use on Open to set recordordsource property to run for the correct data. Then the below procedure, OutputReport is called to output to PDF.
The issue is that for seemingly no reason the velocity of PDF generation slows over time. The process will start at maybe 50 PDF's per minute and slow down substantially. One case slowed to about 9 / minute after 3 hours of processing. Some seem to slow faster than others. And yes there is some variability to the complexity and length of PDF's but not so much that a consistent slow down or one of down to 20% of initial velocity makes sense. I had a report of it slowing to a halt basically.

And then on to the next one. In large batches this has started to slow down in some, maybe all cases as we have multiple copies of the similar application with customized code for the circumstance of these glorified mail merges.

The outer procedure is too involved for anyone to want to wade through here.

We found that disabling Hyperthreading in the BIOS improved velocity of generation but did not stop the slow down.
We've had small improvements and mixed results by setting string variables and tempvars for things like passing SQL to vbNull.
The procedure is set to resume because it tracks which PDF's have been processed - Stopping it and ending the access session restores performance but not stopping and re-executing.

The reports themselves always consist of a Main report that manages things like page headers and footers and initial page so it is standard. Then there is a sub report (level 1) that is data driven and has fields with text format set to "Rich Text". That sub report may 0 to many Level 2 sub reports. Having more level 2 sub reports, most that may be hidden depending on data does seem to make the situation worse in that velocity slows down faster. Memory utilization of Access is stable, it fluctuates but is not just growing so it does not seem to be a memory leak. Both the main report and level 1 sub report have record sources set by tempvars holding the appropriate constructed SQL statements.

With that high level overview, what thoughts on this slowdown over time that is new do any of you have?

I'm using:
Microsoft® Access® for Microsoft 365 MSO (Version 2408 Build 16.0.17928.20114) 64-bit

2408 Build may have been recently installed.

Behavior was replicated on 32 bit office.

We have tried the old shut off end point security things like AV to see if it is the culprit and it is not.

What if any ideas of something to check or reason do you have? No idea is too crazy at this point.... I am at kitchen sink troubleshooting now, I'll try anything.

Sub OutputReport(strReport As String, strFile As String, Optional varOutputFormat As Variant = acFormatPDF)
  'Created 2/20/2018
  'Purpose ensure that the report output is written to disk.
  'Observed behavior is if not and another file created the unwritten file will be lost.
  'If you wait for it, everything is fine.
    'Seems like the write cache buffer is overwritten.
  
  '6/28/2019 JAC
  'Add support for TempVars!ReportError
  
  Dim lngPathCounter As Long
  
  Const conDefaultReportError = "Report either did not initialize or not supported"
  
Retry:
  TempVars!ReportError = conDefaultReportError
  
  
  'DoCmd.OpenReport strReport, acViewPreview 'added for testing 2/27/2020 - Allows for testing if docmd.outputto fails
  
  DoCmd.OutputTo acOutputReport, strReport, varOutputFormat, strFile
  
  Select Case TempVars!ReportError
    Case conDefaultReportError
      MsgBox "Report does not seem to have a Tempvars!ReportError error handler. Please correct or understand it is failing before initialization. " & vbCrLf & "Code will break for debugging." & vbCrLf & "Remember Report code will not run while in break mode...  Ironman (Manual intervention) is the only way to continue."
      Stop
      
      'TempVars!ReportError should be set to zero length string on report open (TempVars!ReportError = "")
      'Error handlers should set TempVars!ReportError
      'Every programmed event should have an Error handler
      
      
      Call Deletefile(strFile)  'Delete bad attempt at file (if it exists)
      
      'If you fixed the report move insertion point past err.raise to Retry, either label above or goto below
      Err.Raise "-1", "mdlMisc.OutputReport", "Unhandled error raised by report object:" & vbCrLf & TempVars!ReportError
      
      GoTo Retry 'Retry the report
      
    Case "" 'Completed no error
      'Welcome to this environment, where OS writes are not as synchronous as you would expect
      'Check that the file that was just written to disk exists iteratively but only so many times in case it is a report object issue
      'Yes I know docmd.output to is a synchronous command but seeing different behavior here.
      lngPathCounter = 0
      While Dir(strFile) = "" And lngPathCounter < 10 'If file doesn't exist and only check up to 9 times...
        lngPathCounter = lngPathCounter + 1
        If lngPathCounter > 5 Then 'Really only expect OS flush to take several loop passes but stop after 5 for programmer check and intervention
          Stop 'Seriously file not here yet?
               'Likely this is representative of report not running after 5 loops (arbitrary assumption).
               'Remember Report code will not run while this procedure in break mode...
               'Recommend checking the report recordsource for records as a starting place. - Most recent problem I saw here was related to missing data
        End If
      Wend
    Case Else
      MsgBox "Error Processing report: " & vbCrLf & "File: " & strFile & vbCrLf & TempVars!ReportError & vbCrLf & "File will be deleted."
      Call Deletefile(strFile)  'Delete bad attempt at file (if it exists)
  End Select

End Sub

 

[Andrzejek]

I would try to set up a little table:
ID Step StartDate StopDate
1 Step1 1/1/2024 8:00:00 1/1/2024 8:00:10
2 Step2 1/1/2024 8:00:10 1/1/2024 8:00:15
3 Step3 1/1/2024 8:00:15 1/1/2024 8:20:10

and chop your code into chunks where you can capture the time when you execute these steps:

Step 1 code:
Insert Into MyTable (Step, StartDate) Values ('Step1', Now())
and after first one, you can do:
Step 2 code:
Update MyTable Set StopDate = Now() Where StopDate Is NULL
Insert Into MyTable (Step, StartDate) Values ('Step2', Now())
and on...

After your program runs and slows down, you will have the data which you can use to calculate durations of how long each step took. This way you can pinpoint which Step(s) took the longest (in my example I would look closer at Step3), or which Step was fast at the beginning but took longer and longer over time.

If you chop your code into (let's say) 10 pieces at the start and find out Step 7 takes the longest over time, then you can just divide just Step 7 into many 'pieces' and repeat the process narrowing down to a small piece of logic that makes your program to slow down. If you 'divide and conquer' enough, you may just get to a particular line of code that is the culprit.

 

[lameid]

This has been confirmed to be an Office 365 issue. Build 2406 is last known to work correctly and Builds 2408 and 2409 are known to definitely have the issue.
We have an active case with Microsoft.