Blog build freezing after update

[rdeago]

As reported by @atiq-cs in #25 (comment):

Hi Guys, It's been a while. Hope you are doing great!

Change in this commit 8c248f0 as part of this PR has regressed build performance. As a result of that, our large blog with 819 posts has started failing since pulling in this change. Our blog successfully builds till commit 8c248f0 is pulled.

To provide more context, our blog usually builds in 6 minutes. Since pulling this change / commit 8c248f0 it has been building for forever. It's also failing on the cloud instance since pulling in this change due to time outs. I request re-reviewing the change introduced and what changed that increased build time dramatically!

Please let me know if you need any other debug / diagnostic info.

Here's output of -- preview,

dotnet run -- preview
[INFO] Statiq Framework version 1.0.0-beta.70+625bd4754bf14f3c6a860587c6d747f4850b1c13
[INFO] Statiq Web version 1.0.0+7f3b58623a7e4ad2542635168bf49d12bb09c299
[INFO] Root path:
       D:/Code/statiq/triage.rdeago
[INFO] Input path(s):
       theme/input
       input
[INFO] Output path:
       output
[INFO] Temp path:
       temp
[INFO] Cache path:
       cache
[INFO] ========== Execution ==========
[INFO] Executing 11 pipelines (AnalyzeContent, Archives, Assets, Content, Data, DirectoryMetadata, Feeds, Inputs, Redirects, SearchIndex, Sitemap)
[INFO] Absolute Execution Date/Time: 2023-08-06 14:32:52
[INFO] Configured Current Date/Time: 2023-08-06 14:32:52
[INFO] Minimum Configured Log Level: Information
[INFO] Cleaned temp directory D:/Code/statiq/triage.rdeago/temp
[INFO] Restored write tracking data from D:/Code/statiq/triage.rdeago/cache/writecache.json
[INFO] Restored Razor compilation cache from D:/Code/statiq/triage.rdeago/cache/razorcache.json with 825 assemblies
[INFO] -> Inputs/Input » Starting Inputs Input phase execution... (0 input document(s), 1 module(s))
[INFO] -> DirectoryMetadata/Input » Starting DirectoryMetadata Input phase execution... (0 input document(s), 1 module(s))
[INFO] <- DirectoryMetadata/Input » Finished DirectoryMetadata Input phase execution (0 output document(s), 217 ms)
[INFO] -> DirectoryMetadata/Process » Starting DirectoryMetadata Process phase execution... (0 input document(s), 1 module(s))
[INFO] <- DirectoryMetadata/Process » Finished DirectoryMetadata Process phase execution (0 output document(s), 1 ms)
[INFO] <- Inputs/Input » Finished Inputs Input phase execution (837 output document(s), 423 ms)
[INFO] -> Inputs/Process » Starting Inputs Process phase execution... (837 input document(s), 8 module(s))
[INFO] <- Inputs/Process » Finished Inputs Process phase execution (836 output document(s), 6106 ms)
[INFO] -> Data/Process » Starting Data Process phase execution... (0 input document(s), 5 module(s))
[INFO] -> Assets/Process » Starting Assets Process phase execution... (0 input document(s), 3 module(s))
[INFO] <- Data/Process » Finished Data Process phase execution (0 output document(s), 29 ms)
[INFO] -> Content/Process » Starting Content Process phase execution... (0 input document(s), 4 module(s))
[INFO] <- Content/Process » Finished Content Process phase execution (809 output document(s), 2407 ms)
[INFO] -> Archives/Process » Starting Archives Process phase execution... (0 input document(s), 3 module(s))
[INFO] <- Assets/Process » Finished Assets Process phase execution (23 output document(s), 3453 ms)
[INFO] <- Archives/Process » Finished Archives Process phase execution (880 output document(s), 87658 ms)
[INFO] -> Feeds/Process » Starting Feeds Process phase execution... (0 input document(s), 3 module(s))
[INFO] <- Feeds/Process » Finished Feeds Process phase execution (2 output document(s), 32270 ms)
[INFO] -> SearchIndex/PostProcess » Starting SearchIndex PostProcess phase execution... (0 input document(s), 1 module(s))
[INFO] <- SearchIndex/PostProcess » Finished SearchIndex PostProcess phase execution (0 output document(s), 0 ms)
[INFO] -> SearchIndex/Output » Starting SearchIndex Output phase execution... (0 input document(s), 1 module(s))
[INFO] <- SearchIndex/Output » Finished SearchIndex Output phase execution (0 output document(s), 3 ms)
[INFO] -> Sitemap/PostProcess » Starting Sitemap PostProcess phase execution... (0 input document(s), 1 module(s))
[INFO] -> Assets/Output » Starting Assets Output phase execution... (23 input document(s), 2 module(s))
[INFO] -> Data/Output » Starting Data Output phase execution... (0 input document(s), 2 module(s))
[INFO] <- Data/Output » Finished Data Output phase execution (0 output document(s), 0 ms)
[INFO] -> Content/PostProcess » Starting Content PostProcess phase execution... (809 input document(s), 1 module(s))
[INFO] <- Assets/Output » Finished Assets Output phase execution (23 output document(s), 36 ms)
[INFO] -> Archives/PostProcess » Starting Archives PostProcess phase execution... (880 input document(s), 1 module(s))
[INFO] -> Feeds/Output » Starting Feeds Output phase execution... (2 input document(s), 2 module(s))
[INFO] <- Feeds/Output » Finished Feeds Output phase execution (2 output document(s), 4 ms)
[INFO] <- Sitemap/PostProcess » Finished Sitemap PostProcess phase execution (1 output document(s), 99 ms)
[INFO] -> Sitemap/Output » Starting Sitemap Output phase execution... (1 input document(s), 1 module(s))
[INFO] <- Sitemap/Output » Finished Sitemap Output phase execution (1 output document(s), 7 ms)
[INFO] [Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager] User profile is available. Using 'C:\Users\Atiq\AppData\Local\ASP.NET\DataProtection-Keys' as key repository and Windows DPAPI to encrypt keys at rest.

[rdeago]

@atiq-cs what puzzles me about this issue is that your --preview output shows all pipelines completing successfully in a few minutes. The freeze seems to happen at a later stage.

Can you post the output of --preview before commit [82c48f0] so we can see what should follow that log entry by XmlKeyManager?

[atiq-cs]

Here you go,
Revert to previous commit,

$ git reset --hard 1d761fe87
HEAD is now at 1d761fe Add support for ImageAttribution metadata

build again,

$ dotnet run -- preview
[INFO] Statiq Framework version 1.0.0-beta.70+625bd4754bf14f3c6a860587c6d747f4850b1c13
[INFO] Statiq Web version 1.0.0+7f3b58623a7e4ad2542635168bf49d12bb09c299
[INFO] Root path:
       D:/Code/statiq/triage.rdeago
[INFO] Input path(s):
       theme/input
       input
[INFO] Output path:
       output
[INFO] Temp path:
       temp
[INFO] Cache path:
       cache
[INFO] ========== Execution ==========
[INFO] Executing 11 pipelines (AnalyzeContent, Archives, Assets, Content, Data, DirectoryMetadata, Feeds, Inputs, Redirects, SearchIndex, Sitemap)
[INFO] Absolute Execution Date/Time: 2023-08-08 07:56:52
[INFO] Configured Current Date/Time: 2023-08-08 07:56:52
[INFO] Minimum Configured Log Level: Information
[INFO] Cleaned temp directory D:/Code/statiq/triage.rdeago/temp
[INFO] Restored write tracking data from D:/Code/statiq/triage.rdeago/cache/writecache.json
[INFO] Restored Razor compilation cache from D:/Code/statiq/triage.rdeago/cache/razorcache.json with 825 assemblies
[INFO] -> Inputs/Input » Starting Inputs Input phase execution... (0 input document(s), 1 module(s))
[INFO] -> DirectoryMetadata/Input » Starting DirectoryMetadata Input phase execution... (0 input document(s), 1 module(s))
[INFO] <- DirectoryMetadata/Input » Finished DirectoryMetadata Input phase execution (0 output document(s), 605 ms)
[INFO] -> DirectoryMetadata/Process » Starting DirectoryMetadata Process phase execution... (0 input document(s), 1 module(s))
[INFO] <- DirectoryMetadata/Process » Finished DirectoryMetadata Process phase execution (0 output document(s), 3 ms)
[INFO] <- Inputs/Input » Finished Inputs Input phase execution (837 output document(s), 838 ms)
[INFO] -> Inputs/Process » Starting Inputs Process phase execution... (837 input document(s), 8 module(s))
[INFO] <- Inputs/Process » Finished Inputs Process phase execution (836 output document(s), 9423 ms)
[INFO] -> Assets/Process » Starting Assets Process phase execution... (0 input document(s), 3 module(s))
[INFO] -> Data/Process » Starting Data Process phase execution... (0 input document(s), 5 module(s))
[INFO] <- Data/Process » Finished Data Process phase execution (0 output document(s), 33 ms)
[INFO] -> Content/Process » Starting Content Process phase execution... (0 input document(s), 4 module(s))
[INFO] <- Content/Process » Finished Content Process phase execution (809 output document(s), 1979 ms)
[INFO] -> Archives/Process » Starting Archives Process phase execution... (0 input document(s), 3 module(s))
[INFO] <- Assets/Process » Finished Assets Process phase execution (23 output document(s), 3621 ms)
[INFO] <- Archives/Process » Finished Archives Process phase execution (880 output document(s), 102433 ms)
[INFO] -> Feeds/Process » Starting Feeds Process phase execution... (0 input document(s), 3 module(s))
[INFO] <- Feeds/Process » Finished Feeds Process phase execution (2 output document(s), 37287 ms)
[INFO] -> SearchIndex/PostProcess » Starting SearchIndex PostProcess phase execution... (0 input document(s), 1 module(s))
[INFO] <- SearchIndex/PostProcess » Finished SearchIndex PostProcess phase execution (0 output document(s), 0 ms)
[INFO] -> SearchIndex/Output » Starting SearchIndex Output phase execution... (0 input document(s), 1 module(s))
[INFO] -> Data/Output » Starting Data Output phase execution... (0 input document(s), 2 module(s))
[INFO] -> Content/PostProcess » Starting Content PostProcess phase execution... (809 input document(s), 1 module(s))
[INFO] -> Archives/PostProcess » Starting Archives PostProcess phase execution... (880 input document(s), 1 module(s))
[INFO] -> Sitemap/PostProcess » Starting Sitemap PostProcess phase execution... (0 input document(s), 1 module(s))
[INFO] -> Assets/Output » Starting Assets Output phase execution... (23 input document(s), 2 module(s))
[INFO] -> Feeds/Output » Starting Feeds Output phase execution... (2 input document(s), 2 module(s))
[INFO] <- Data/Output » Finished Data Output phase execution (0 output document(s), 4 ms)
[INFO] <- SearchIndex/Output » Finished SearchIndex Output phase execution (0 output document(s), 4 ms)
[INFO] <- Assets/Output » Finished Assets Output phase execution (23 output document(s), 8 ms)
[INFO] <- Feeds/Output » Finished Feeds Output phase execution (2 output document(s), 9 ms)
[INFO] <- Sitemap/PostProcess » Finished Sitemap PostProcess phase execution (1 output document(s), 55 ms)
[INFO] -> Sitemap/Output » Starting Sitemap Output phase execution... (1 input document(s), 1 module(s))
[INFO] <- Sitemap/Output » Finished Sitemap Output phase execution (1 output document(s), 3 ms)
[INFO] [Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager] User profile is available. Using 'C:\Users\Atiq\AppData\Local\ASP.NET\DataProtection-Keys' as key repository and Windows DPAPI to encrypt keys at rest.
[INFO] <- Content/PostProcess » Finished Content PostProcess phase execution (809 output document(s), 111518 ms)
[INFO] -> Content/Output » Starting Content Output phase execution... (809 input document(s), 2 module(s))
[INFO] <- Content/Output » Finished Content Output phase execution (809 output document(s), 1404 ms)
[INFO] <- Archives/PostProcess » Finished Archives PostProcess phase execution (880 output document(s), 192806 ms)
[INFO] -> Redirects/PostProcess » Starting Redirects PostProcess phase execution... (0 input document(s), 2 module(s))
[INFO] -> Archives/Output » Starting Archives Output phase execution... (880 input document(s), 2 module(s))
[INFO] <- Redirects/PostProcess » Finished Redirects PostProcess phase execution (0 output document(s), 7 ms)
[INFO] -> Redirects/Output » Starting Redirects Output phase execution... (0 input document(s), 1 module(s))
[INFO] <- Redirects/Output » Finished Redirects Output phase execution (0 output document(s), 0 ms)
[INFO] <- Archives/Output » Finished Archives Output phase execution (880 output document(s), 191 ms)
[INFO] -> AnalyzeContent/Input » Starting AnalyzeContent Input phase execution... (0 input document(s), 1 module(s))
[INFO] <- AnalyzeContent/Input » Finished AnalyzeContent Input phase execution (1712 output document(s), 1 ms)
[INFO] AnalyzeContent/Process » Running 3 analyzers (FencedCodeBlocksShouldHaveLanguage, ValidateRelativeLinks, ValidateAbsoluteLinks)
[INFO] Removed 3 stale Razor assemblies from the cache
[INFO] Cached and saved 3 new Razor assemblies
[INFO] Deleted 0 stale cached Razor assembly files
[INFO] Cleaned 0 files not written to output directory D:/Code/statiq/triage.rdeago/output during current execution
[INFO] ========== Execution Summary ==========

Number of output documents per pipeline and phase:

 | Pipeline          | Input        | Process         | PostProcess     | Output        | Total Time |
 |---------------------------------------------------------------------------------------------------|
 | AnalyzeContent    | 1712 (1 ms)  |                 |                 |               | 1 ms       |
 | Archives          |              | 880 (102433 ms) | 880 (192806 ms) | 880 (191 ms)  | 295430 ms  |
 | Assets            |              | 23 (3621 ms)    |                 | 23 (8 ms)     | 3629 ms    |
 | Content           |              | 809 (1979 ms)   | 809 (111518 ms) | 809 (1404 ms) | 114901 ms  |
 | Data              |              | 0 (33 ms)       |                 | 0 (4 ms)      | 37 ms      |
 | DirectoryMetadata | 0 (605 ms)   | 0 (3 ms)        |                 |               | 608 ms     |
 | Feeds             |              | 2 (37287 ms)    |                 | 2 (9 ms)      | 37296 ms   |
 | Inputs            | 837 (838 ms) | 836 (9423 ms)   |                 |               | 10261 ms   |
 | Redirects         |              |                 | 0 (7 ms)        | 0 (0 ms)      | 7 ms       |
 | SearchIndex       |              |                 | 0 (0 ms)        | 0 (4 ms)      | 4 ms       |
 | Sitemap           |              |                 | 1 (55 ms)       | 1 (3 ms)      | 58 ms      |

Pipeline phase timeline:

 | Pipeline          | Timeline (344997 total ms not including overhead)                                    |
 |----------------------------------------------------------------------------------------------------------|
 | AnalyzeContent    |                                                                                  I   |
 | Archives          |    P-----------------------         T-------------------------------------------O    |
 | Assets            |    P                                O                                                |
 | Content           |    P                                T-------------------------O                      |
 | Data              |    P                                O                                                |
 | DirectoryMetadata | IP                                                                                   |
 | Feeds             |                            P--------O                                                |
 | Inputs            | IP-                                                                                  |
 | Redirects         |                                                                                 TO   |
 | SearchIndex       |                                     TO                                               |
 | Sitemap           |                                     TO                                               |


[INFO] ========== Analyzer Results ==========
[WARN] [D:/Code/statiq/triage.rdeago/theme/input/index.cshtml => page/267.html] Could not validate relative link: <img src="../../images/2008/10-30_obama-yahoo.jpg" alt="Democrat Barack Obama.(AP)"> (ValidateRelativeLinks)
[WARN] 1 total relative links could not be validated (ValidateRelativeLinks)
[INFO] ========== Completed ==========
[INFO] 1715 total files output (written or already existed)
[INFO] 2 actual files written
[INFO] 1713 files already existed
[INFO] Finished in 346571 ms:
[INFO] - Before Engine Execution Clean in 378 ms
[INFO] - Before Engine Execution Events in 369 ms
[INFO] - Analyzer Before Engine Execution Events in 3 ms
[INFO] - Engine Execution in 345665 ms
[INFO] - After Engine Execution Events in 122 ms
[INFO] - After Engine Execution Clean in 27 ms
[INFO] Preview server listening at http://localhost:5080 (on any hostname/IP) and serving from path D:/Code/statiq/triage.rdeago/output with LiveReload support
[INFO] Watching paths(s) theme/input, input
[INFO] Type Ctrl-C or "Exit()" to exit and "Help()" for global methods and properties

[atiq-cs]

@rdeago @daveaglick did you get a chance to look into this?

@rdeago lmk if you need anything else. Thanks for looking into this.

If a fix is needed, it's better applied ...

Have you assessed if a fix is needed yet?

[atiq-cs]

@rdeago is there any update? Do you have any question?

[daveaglick]

Let's go ahead and take a little look at this from a root-cause analysis before merging #35 (though thanks for PRing that if we can't get to the bottom of it). The part that I find interesting is that IsPage is a fairly simple computed value:

IsPage: => Context.Outputs.FilterSources(Context.GetString("PageSources")).ContainsById(Document)

Given the changes you're backing out in #35 that fix the performance, I can see a couple of possibilities for the degradation...

1. Perhaps IsPage is taking a while to compute. PageSources is just a string (PageSources: pages/**/*), but the FilterSources method uses the globber, which maybe is taking a while on a large site.
2. Do you have anything in your _page-after-content.cshtml file? I'm guessing not, but worth checking. If so, then that may be what's taking the time.

Any chance your site code is somewhere I can get to it and run some profiling?

[atiq-cs]

1. could be
2. Nope

Any chance your site code is somewhere I can get to it and run some profiling?

Emailed you, please check junk / spam folder.

[daveaglick]

Emailed you, please check junk / spam folder.

Thanks, got it! Taking a look at this today, hopefully I'll at least get an idea where the performance degradation is coming from, if not a fix.

[daveaglick]

I think I have a solution - can you try updating to the latest version of Statiq without the changes in #35 (I.e. leave the ispage stuff in the theme). I'm curious if that resolves the issue, and if it feels snappier in general. If so, I'll fill in the details on what changed.

[atiq-cs]

My local build succeeded with above suggestion. Also succeeded in cloud instance.

[atiq-cs]

Feel free to close this issue @daveaglick :)

[daveaglick]

Awesome! I actually don't remember what changed at this point 😂 but glad it's holding strong.