Question: "Starting Service Tier" sometimes takes very very long time on multitenant restores

[Koubek]

Hello @freddydk and every one else,

I am curious if someone else has been facing the same problem. This is not anything new, we have seen this behavior for a very long time but as we use restores with containers more and more, this is getting even more annoying than before. And tbh, I believe this is not probably related to containers at all (so maybe also reporting the issue here is not the best I could do - sorry, but maybe you could NAVigate ;) me to a better place).

Our pain is in the time that is needed to start the service tier when we use those with restores of a multitenant environment we host. We basically run the restore (app and selected tenant database) and then hook up the container.

You can see the critical part of the logs coming from the affected container:

...
2022-08-29T08:40:09.546531900Z WARNING: The new settings value will not take effect until you stop and restart the service.
2022-08-29T08:40:09.552210300Z NP: Azure Key Vault setup complete.
2022-08-29T08:40:09.574191900Z Starting Service Tier
2022-08-29T09:02:41.677069300Z Registering event sources
2022-08-29T09:02:41.767116300Z Creating DotNetCore Web Server Instance
2022-08-29T09:02:45.669619000Z Enabling rewrite rule: Don't rewrite system files
...

You can see Starting Service Tier takes here around 20 minutes.

During this time the app db consumes 100% CPU on Azure SQL on the following queries (the first one is definitely the most relevant one as it consumes around 90% of all time being spent on):

(@0 uniqueidentifier,@1 uniqueidentifier,@2 uniqueidentifier,@3 uniqueidentifier,@4 uniqueidentifier,@5 uniqueidentifier,@6 uniqueidentifier,@7 uniqueidentifier,@8 uniqueidentifier,@9 uniqueidentifier,@10 uniqueidentifier,@11 uniqueidentifier,@12 uniqueidentifier,@13 uniqueidentifier,@14 uniqueidentifier,@15 uniqueidentifier,@16 uniqueidentifier,@17 uniqueidentifier,@18 uniqueidentifier,@19 uniqueidentifier,@20 uniqueidentifier,@21 uniqueidentifier,@22 uniqueidentifier,@23 uniqueidentifier,@24 uniqueidentifier,@25 uniqueidentifier,@26 uniqueidentifier,@27 uniqueidentifier,@28 uniqueidentifier,@29 uniqueidentifier,@30 uniqueidentifier,@31 uniqueidentifier,@32 uniqueidentifier,@33 uniqueidentifier,@34 uniqueidentifier,@35 uniqueidentifier,@36 uniqueidentifier,@37 uniqueidentifier,@38 uniqueidentifier,@39 uniqueidentifier,@40 uniqueidentifier,@41 uniqueidentifier,@42 uniqueidentifier,@43 uniqueidentifier,@44 uniqueidentifier,@45 uniqueidentifier,@46 uniqueidentifier,@47 uniqueidentifier,@48 uniqueidentifier,@49 uniqueidentifier,@50 uniqueidentifier,@51 uniqueidentifier,@52 uniqueidentifier,@53 uniqueidentifier,@54 uniqueidentifier,@55 uniqueidentifier,@56 uniqueidentifier,@57 uniqueidentifier,@58 uniqueidentifier,@59 uniqueidentifier,@60 uniqueidentifier,@61 uniqueidentifier,@62 uniqueidentifier,@63 uniqueidentifier,@64 uniqueidentifier,@65 uniqueidentifier,@66 uniqueidentifier,@67 uniqueidentifier,@68 uniqueidentifier,@69 uniqueidentifier,@70 uniqueidentifier,@71 uniqueidentifier,@72 uniqueidentifier,@73 uniqueidentifier,@74 uniqueidentifier,@75 uniqueidentifier,@76 uniqueidentifier,@77 uniqueidentifier,@78 uniqueidentifier,@79 uniqueidentifier,@80 uniqueidentifier,@81 uniqueidentifier,@82 uniqueidentifier,@83 uniqueidentifier,@84 uniqueidentifier,@85 uniqueidentifier,@86 uniqueidentifier,@87 uniqueidentifier,@88 uniqueidentifier,@89 uniqueidentifier,@90 uniqueidentifier,@91 uniqueidentifier,@92 uniqueidentifier,@93 uniqueidentifier,@94 uniqueidentifier,@95 uniqueidentifier,@96 uniqueidentifier,@97 uniqueidentifier,@98 uniqueidentifier,@99 uniqueidentifier,@100 uniqueidentifier,@101 uniqueidentifier,@102 uniqueidentifier,@103 uniqueidentifier,@104 uniqueidentifier,@105 uniqueidentifier,@106 uniqueidentifier,@107 uniqueidentifier,@108 uniqueidentifier,@109 uniqueidentifier,@110 uniqueidentifier,@111 uniqueidentifier,@112 uniqueidentifier,@113 uniqueidentifier,@114 uniqueidentifier,@115 uniqueidentifier,@116 uniqueidentifier,@117 uniqueidentifier,@118 uniqueidentifier,@119 uniqueidentifier,@120 uniqueidentifier,@121 uniqueidentifier,@122 uniqueidentifier,@123 uniqueidentifier,@124 uniqueidentifier,@125 uniqueidentifier,@126 uniqueidentifier,@127 uniqueidentifier,@128 uniqueidentifier,@129 uniqueidentifier,@130 uniqueidentifier,@131 uniqueidentifier,@132 uniqueidentifier,@133 uniqueidentifier,@134 uniqueidentifier,@135 uniqueidentifier,@136 uniqueidentifier,@137 uniqueidentifier,@138 uniqueidentifier,@139 uniqueidentifier,@140 uniqueidentifier,@141 uniqueidentifier,@142 uniqueidentifier,@143 uniqueidentifier,@144 uniqueidentifier,@145 uniqueidentifier,@146 uniqueidentifier,@147 uniqueidentifier,@148 uniqueidentifier,@149 uniqueidentifier,@150 uniqueidentifier,@151 uniqueidentifier,@152 uniqueidentifier,@153 uniqueidentifier,@154 uniqueidentifier,@155 uniqueidentifier,@156 uniqueidentifier,@157 uniqueidentifier,@158 uniqueidentifier,@159 uniqueidentifier,@160 uniqueidentifier,@161 uniqueidentifier,@162 uniqueidentifier,@163 uniqueidentifier,@164 uniqueidentifier,@165 uniqueidentifier,@166 uniqueidentifier,@167 uniqueidentifier,@168 uniqueidentifier,@169 uniqueidentifier,@170 uniqueidentifier,@171 uniqueidentifier,@172 uniqueidentifier,@173 uniqueidentifier,@174 uniqueidentifier,@175 uniqueidentifier,@176 uniqueidentifier,@177 uniqueidentifier,@178 uniqueidentifier,@179 uniqueidentifier,@180 uniqueidentifier,@181 uniqueidentifier,@182 uniqueidentifier,@183 uniqueidentifier,@184 uniqueidentifier,@185 uniqueidentifier,@186 uniqueidentifier,@187 uniqueidentifier,@188 uniqueidentifier,@189 uniqueidentifier,@190 uniqueidentifier,@191 uniqueidentifier,@192 uniqueidentifier,@193 uniqueidentifier,@194 uniqueidentifier,@195 uniqueidentifier,@196 uniqueidentifier,@197 uniqueidentifier,@198 uniqueidentifier,@199 uniqueidentifier)SELECT "2000000207"."timestamp","2000000207"."Runtime Package ID","2000000207"."Object Type","2000000207"."Object ID","2000000207"."Package ID","2000000207"."Metadata Format",DATALENGTH("2000000207"."Metadata"),DATALENGTH("2000000207"."User Code"),DATALENGTH("2000000207"."User AL Code"),"2000000207"."Metadata Version","2000000207"."Object Subtype","2000000207"."Object Name","2000000207"."Metadata Hash","2000000207"."User Code Hash","2000000207"."Object Flags","2000000207"."$systemId","2000000207"."$systemCreatedAt","2000000207"."$systemCreatedBy","2000000207"."$systemModifiedAt","2000000207"."$systemModifiedBy" FROM "17WEU-DK_APP-A-539217".dbo."Application Object Metadata" "2000000207"  WITH(READUNCOMMITTED)  WHERE ("2000000207"."Runtime Package ID"=@0 OR "2000000207"."Runtime Package ID"=@1 OR ("2000000207"."Runtime Package ID"=@2 OR "2000000207"."Runtime Package ID"=@3) OR ("2000000207"."Runtime Package ID"=@4 OR "2000000207"."Runtime Package ID"=@5 OR ("2000000207"."Runtime Package ID"=@6 OR "2000000207"."Runtime Package ID"=@7)) OR ("2000000207"."Runtime Package ID"=@8 OR "2000000207"."Runtime Package ID"=@9 OR ("2000000207"."Runtime Package ID"=@10 OR "2000000207"."Runtime Package ID"=@11) OR ("2000000207"."Runtime Package ID"=@12 OR "2000000207"."Runtime Package ID"=@13 OR ("2000000207"."Runtime Package ID"=@14 OR "2000000207"."Runtime Package ID"=@15))) OR ("2000000207"."Runtime Package ID"=@16 OR "2000000207"."Runtime Package ID"=@17 OR ("2000000207"."Runtime Package ID"=@18 OR "2000000207"."Runtime Package ID"=@19) OR ("2000000207"."Runtime Package ID"=@20 OR "2000000207"."Runtime Package ID"=@21 OR ("2000000207"."Runtime Package ID"=@22 OR "2000000207"."Runtime Package ID"=@23)) OR ("2000000207"."Runtime Package ID"=@24 OR "2000000207"."Runtime Package ID"=@25 OR ("2000000207"."Runtime Package ID"=@26 OR "2000000207"."Runtime Package ID"=@27) OR ("2000000207"."Runtime Package ID"=@28 OR "2000000207"."Runtime Package ID"=@29 OR ("2000000207"."Runtime Package ID"=@30 OR "2000000207"."Runtime Package ID"=@31)))) OR ("2000000207"."Runtime Package ID"=@32 OR "2000000207"."Runtime Package ID"=@33 OR ("2000000207"."Runtime Package ID"=@34 OR "2000000207"."Runtime Package ID"=@35) OR ("2000000207"."Runtime Package ID"=@36 OR "2000000207"."Runtime Package ID"=@37 OR ("2000000207"."Runtime Package ID"=@38 OR "2000000207"."Runtime Package ID"=@39)) OR ("2000000207"."Runtime Package ID"=@40 OR "2000000207"."Runtime Package ID"=@41 OR ("2000000207"."Runtime Package ID"=@42 OR "2000000207"."Runtime Package ID"=@43) OR ("2000000207"."Runtime Package ID"=@44 OR "2000000207"."Runtime Package ID"=@45 OR ("2000000207"."Runtime Package ID"=@46 OR "2000000207"."Runtime Package ID"=@47))) OR ("2000000207"."Runtime Package ID"=@48 OR "2000000207"."Runtime Package ID"=@49 OR ("2000000207"."Runtime Package ID"=@50 OR "2000000207"."Runtime Package ID"=@51) OR ("2000000207"."Runtime Package ID"=@52 OR "2000000207"."Runtime Package ID"=@53 OR ("2000000207"."Runtime Package ID"=@54 OR "2000000207"."Runtime Package ID"=@55)) OR ("2000000207"."Runtime Package ID"=@56 OR "2000000207"."Runtime Package ID"=@57 OR ("2000000207"."Runtime Package ID"=@58 OR "2000000207"."Runtime Package ID"=@59) OR ("2000000207"."Runtime Package ID"=@60 OR "2000000207"."Runtime Package ID"=@61 OR ("2000000207"."Runtime Package ID"=@62 OR "2000000207"."Runtime Package ID"=@63))))) OR ("2000000207"."Runtime Package ID"=@64 OR "2000000207"."Runtime Package ID"=@65 OR ("2000000207"."Runtime Package ID"=@66 OR "2000000207"."Runtime Package ID"=@67) OR ("2000000207"."Runtime Package ID"=@68 OR "2000000207"."Runtime Package ID"=@69 OR ("2000000207"."Runtime Package ID"=@70 OR "2000000207"."Runtime Package ID"=@71)) OR ("2000000207"."Runtime Package ID"=@72 OR "2000000207"."Runtime Package ID"=@73 OR ("2000000207"."Runtime Package ID"=@74 OR "2000000207"."Runtime Package ID"=@75) OR ("2000000207"."Runtime Package ID"=@76 OR "2000000207"."Runtime Package ID"=@77 OR ("2000000207"."Runtime Package ID"=@78 OR "2000000207"."Runtime Package ID"=@79))) OR ("2000000207"."Runtime Package ID"=@80 OR "2000000207"."Runtime Package ID"=@81 OR ("2000000207"."Runtime Package ID"=@82 OR "2000000207"."Runtime Package ID"=@83) OR ("2000000207"."Runtime Package ID"=@84 OR "2000000207"."Runtime Package ID"=@85 OR ("2000000207"."Runtime Package ID"=@86 OR "2000000207"."Runtime Package ID"=@87)) OR ("2000000207"."Runtime Package ID"=@88 OR "2000000207"."Runtime Package ID"=@89 OR ("2000000207"."Runtime Package ID"=@90 OR "2000000207"."Runtime Package ID"=@91) OR ("2000000207"."Runtime Package ID"=@92 OR "2000000207"."Runtime Package ID"=@93 OR ("2000000207"."Runtime Package ID"=@94 OR "2000000207"."Runtime Package ID"=@95)))) OR ("2000000207"."Runtime Package ID"=@96 OR "2000000207"."Runtime Package ID"=@97 OR ("2000000207"."Runtime Package ID"=@98 OR "2000000207"."Runtime Package ID"=@99) OR ("2000000207"."Runtime Package ID"=@100 OR "2000000207"."Runtime Package ID"=@101 OR ("2000000207"."Runtime Package ID"=@102 OR "2000000207"."Runtime Package ID"=@103)) OR ("2000000207"."Runtime Package ID"=@104 OR "2000000207"."Runtime Package ID"=@105 OR ("2000000207"."Runtime Package ID"=@106 OR "2000000207"."Runtime Package ID"=@107) OR ("2000000207"."Runtime Package ID"=@108 OR "2000000207"."Runtime Package ID"=@109 OR ("2000000207"."Runtime Package ID"=@110 OR "2000000207"."Runtime Package ID"=@111))) OR ("2000000207"."Runtime Package ID"=@112 OR "2000000207"."Runtime Package ID"=@113 OR ("2000000207"."Runtime Package ID"=@114 OR "2000000207"."Runtime Package ID"=@115) OR ("2000000207"."Runtime Package ID"=@116 OR "2000000207"."Runtime Package ID"=@117 OR ("2000000207"."Runtime Package ID"=@118 OR "2000000207"."Runtime Package ID"=@119)) OR ("2000000207"."Runtime Package ID"=@120 OR "2000000207"."Runtime Package ID"=@121 OR ("2000000207"."Runtime Package ID"=@122 OR "2000000207"."Runtime Package ID"=@123) OR ("2000000207"."Runtime Package ID"=@124 OR "2000000207"."Runtime Package ID"=@125 OR ("2000000207"."Runtime Package ID"=@126 OR "2000000207"."Runtime Package ID"=@127)))))) OR ("2000000207"."Runtime Package ID"=@128 OR "2000000207"."Runtime Package ID"=@129 OR ("2000000207"."Runtime Package ID"=@130 OR "2000000207"."Runtime Package ID"=@131) OR ("2000000207"."Runtime Package ID"=@132 OR "2000000207"."Runtime Package ID"=@133 OR ("2000000207"."Runtime Package ID"=@134 OR "2000000207"."Runtime Package ID"=@135)) OR ("2000000207"."Runtime Package ID"=@136 OR "2000000207"."Runtime Package ID"=@137 OR ("2000000207"."Runtime Package ID"=@138 OR "2000000207"."Runtime Package ID"=@139) OR ("2000000207"."Runtime Package ID"=@140 OR "2000000207"."Runtime Package ID"=@141 OR ("2000000207"."Runtime Package ID"=@142 OR "2000000207"."Runtime Package ID"=@143))) OR ("2000000207"."Runtime Package ID"=@144 OR "2000000207"."Runtime Package ID"=@145 OR ("2000000207"."Runtime Package ID"=@146 OR "2000000207"."Runtime Package ID"=@147) OR ("2000000207"."Runtime Package ID"=@148 OR "2000000207"."Runtime Package ID"=@149 OR ("2000000207"."Runtime Package ID"=@150 OR "2000000207"."Runtime Package ID"=@151)) OR ("2000000207"."Runtime Package ID"=@152 OR "2000000207"."Runtime Package ID"=@153 OR ("2000000207"."Runtime Package ID"=@154 OR "2000000207"."Runtime Package ID"=@155) OR ("2000000207"."Runtime Package ID"=@156 OR "2000000207"."Runtime Package ID"=@157 OR ("2000000207"."Runtime Package ID"=@158 OR "2000000207"."Runtime Package ID"=@159)))) OR ("2000000207"."Runtime Package ID"=@160 OR "2000000207"."Runtime Package ID"=@161 OR ("2000000207"."Runtime Package ID"=@162 OR "2000000207"."Runtime Package ID"=@163) OR ("2000000207"."Runtime Package ID"=@164 OR "2000000207"."Runtime Package ID"=@165 OR ("2000000207"."Runtime Package ID"=@166 OR "2000000207"."Runtime Package ID"=@167)) OR ("2000000207"."Runtime Package ID"=@168 OR "2000000207"."Runtime Package ID"=@169 OR ("2000000207"."Runtime Package ID"=@170 OR "2000000207"."Runtime Package ID"=@171) OR ("2000000207"."Runtime Package ID"=@172 OR "2000000207"."Runtime Package ID"=@173 OR ("2000000207"."Runtime Package ID"=@174 OR "2000000207"."Runtime Package ID"=@175))) OR ("2000000207"."Runtime Package ID"=@176 OR "2000000207"."Runtime Package ID"=@177 OR ("2000000207"."Runtime Package ID"=@178 OR "2000000207"."Runtime Package ID"=@179) OR ("2000000207"."Runtime Package ID"=@180 OR "2000000207"."Runtime Package ID"=@181 OR ("2000000207"."Runtime Package ID"=@182 OR "2000000207"."Runtime Package ID"=@183)) OR ("2000000207"."Runtime Package ID"=@184 OR "2000000207"."Runtime Package ID"=@185 OR ("2000000207"."Runtime Package ID"=@186 OR "2000000207"."Runtime Package ID"=@187) OR ("2000000207"."Runtime Package ID"=@188 OR "2000000207"."Runtime Package ID"=@189 OR ("2000000207"."Runtime Package ID"=@190 OR "2000000207"."Runtime Package ID"=@191))))) OR ("2000000207"."Runtime Package ID"=@192 OR "2000000207"."Runtime Package ID"=@193 OR ("2000000207"."Runtime Package ID"=@194 OR "2000000207"."Runtime Package ID"=@195) OR ("2000000207"."Runtime Package ID"=@196 OR "2000000207"."Runtime Package ID"=@197 OR ("2000000207"."Runtime Package ID"=@198 OR "2000000207"."Runtime Package ID"=@199))))) ORDER BY "Runtime Package ID" ASC,"Object Type" ASC,"Object ID" ASC OPTION(OPTIMIZE FOR UNKNOWN, FAST 50)

SELECT [Runtime Package ID], [Blob] FROM [17WEU-DK_APP-A-539217].[dbo].[Published Application] WHERE [Runtime Package ID] IN ([List-of-GUIDs])

NST then goes up and everything works fine but the time needed to start containers is just crazily long.

[Koubek]

No idea on this topic?

[Koubek]

@freddydk , please, is there any chance to get some traces of what is happening during NST start and what could actually take so long?

[rdebath]

I think this is compilation of the MS/AL to C# and then DLL files.
The customsettings.config file has an option
<add key="CompileBusinessApplicationAtStartup" value="true" />
When it's true, the default, all objects are compiled on first startup with a new DB.
When it's false objects are only compiled as needed and so are initially very slow.
The compiled DLLs are stored somewhere like C:\ProgramData\Microsoft\Microsoft Dynamics NAV\240\Server

You first SQL might be to do with the event subscriptions, this probably gets run even with the above flag turned off.

[freddydk]

I tried setting the CompileBusinessApplicationAtStartup to false - it doesn't change the performance when starting a container on my machine.
I did however find that on my machine - starting a container using process isolation takes much longer than using HyperV isolation, I don't know if that information can help.
On the inner details of what the NST is doing during startup, you can try to post a message on Yammer (Viva Engage) and see if anybody from the server team can help you there.