Hey team 👋
Was unsure if this would come under bug or enhancement, but given… that this is preventing my provider from creating a plan, I went for bug.
tl;dr: we have a resource that accepts a large and deeply nested object. Trace and debug logs produced by the SDK around setting defaults/state modifications/etc are so verbose that it causes planning to become much more expensive (16s -> 527s, so 32x).
Having profiled the provider as it produces the plan, it appears the majority of the cost comes from the context based logger. Generally logging this much can be expensive, but particularly reflection-based runtime loggers that pull context.Value frequently, as the time adds up.
Attaching the profile below where you can see of the 28.52s sample, we spent 22.38s in `context.(*valueCtx).Value` as part of the logging library, and the rest in logging adjacent functions.
```
(pprof) top 100Showing nodes accounting for 28.08s, 98.46% of 28.52s totalDropped 105 nodes (cum <= 0.14s)
flat flat% sum% cum cum% 15.34s 53.79% 53.79% 19.21s 67.36% runtime.efaceeq 3.76s 13.18% 66.97% 3.77s 13.22% runtime.strequal
3.49s 12.24% 79.21% 3.49s 12.24% syscall.syscall 3.16s 11.08% 90.29% 22.38s 78.47% context.value 1.50s 5.26% 95.55% 1.50s 5.26% runtime.madvise
0.66s 2.31% 97.86% 0.66s 2.31% runtime.memclrNoHeapPointers
0.16s 0.56% 98.42% 0.20s 0.7% runtime.scanobject
0.01s 0.035% 98.46% 0.76s 2.66% runtime.mallocgc
0 0% 98.46% 22.38s 78.47% context.(*valueCtx).Value
0 0% 98.46% 4.21s 14.76% github.com/hashicorp/go-hclog.(*intLogger).Trace
0 0% 98.46% 4.29s 15.04% github.com/hashicorp/go-hclog.(*intLogger).log
0 0% 98.46% 0.80s 2.81% github.com/hashicorp/go-hclog.(*intLogger).logJSON
0 0% 98.46% 3.49s 12.24% github.com/hashicorp/go-hclog.(*writer).Flush
0 0% 98.46% 0.65s 2.28% github.com/hashicorp/go-hclog.intLogger.jsonMapEntry
0 0% 98.46% 26.76s 93.83% github.com/hashicorp/terraform-plugin-framework/internal/fwserver.(*Server).PlanResourceChange
0 0% 98.46% 26.76s 93.83% github.com/hashicorp/terraform-plugin-framework/internal/fwserver.MarkComputedNilsAsUnknown.func1
0 0% 98.46% 0.67s 2.35% github.com/hashicorp/terraform-plugin-framework/internal/logging.FrameworkDebug (inline)
0 0% 98.46% 26.07s 91.41% github.com/hashicorp/terraform-plugin-framework/internal/logging.FrameworkTrace (inline)
0 0% 98.46% 26.76s 93.83% github.com/hashicorp/terraform-plugin-framework/internal/proto6server.(*Server).PlanResourceChange
0 0% 98.46% 26.76s 93.83% github.com/hashicorp/terraform-plugin-go/tfprotov6/internal/tfplugin6._Provider_PlanResourceChange_Handler
0 0% 98.46% 26.76s 93.83% github.com/hashicorp/terraform-plugin-go/tfprotov6/tf6server.(*server).PlanResourceChange
0 0% 98.46% 26.76s 93.83% github.com/hashicorp/terraform-plugin-go/tftypes.Transform (inline)
0 0% 98.46% 26.76s 93.83% github.com/hashicorp/terraform-plugin-go/tftypes.transform
0 0% 98.46% 22.39s 78.51% github.com/hashicorp/terraform-plugin-log/internal/logging.GetSDKSubsystemLogger
0 0% 98.46% 0.67s 2.35% github.com/hashicorp/terraform-plugin-log/tfsdklog.SubsystemDebug
0 0% 98.46% 26.07s 91.41% github.com/hashicorp/terraform-plugin-log/tfsdklog.SubsystemTrace
0 0% 98.46% 26.76s 93.83% google.golang.org/grpc.(*Server).handleStream
0 0% 98.46% 26.76s 93.83% google.golang.org/grpc.(*Server).processUnaryRPC
0 0% 98.46% 26.76s 93.83% google.golang.org/grpc.(*Server).serveStreams.func1.2
0 0% 98.46% 3.49s 12.24% internal/poll.(*FD).Write
0 0% 98.46% 3.49s 12.24% internal/poll.ignoringEINTRIO (inline)
0 0% 98.46% 3.49s 12.24% os.(*File).Write
0 0% 98.46% 3.49s 12.24% os.(*File).write (inline)
0 0% 98.46% 1.54s 5.40% runtime.(*mheap).alloc.func1
0 0% 98.46% 1.54s 5.40% runtime.(*mheap).allocSpan
0 0% 98.46% 0.20s 0.7% runtime.gcBgMarkWorker
0 0% 98.46% 0.20s 0.7% runtime.gcBgMarkWorker.func2
0 0% 98.46% 0.20s 0.7% runtime.gcDrain
0 0% 98.46% 0.62s 2.17% runtime.mapassign_faststr
0 0% 98.46% 0.59s 2.07% runtime.newobject (inline)
0 0% 98.46% 1.50s 5.26% runtime.sysUsed (inline)
0 0% 98.46% 1.50s 5.26% runtime.sysUsedOS (inline)
0 0% 98.46% 1.75s 6.14% runtime.systemstack
0 0% 98.46% 3.49s 12.24% syscall.Write (inline)
0 0% 98.46% 3.49s 12.24% syscall.write
```
### Module version
```
github.com/hashicorp/terraform-plugin-framework v1.2.0
```
Definitely running latest as I've pulled the repo locally to try investigating this.
### Relevant provider source code
PlanResourceChange (https://github.com/hashicorp/terraform-plugin-framework/blob/main/internal/fwserver/server_planresourcechange.go#L44) is where we're spending all our time, which is due to the many log calls.
Applying this patch is what gives the 32x improvement in plan speed:
```diff
diff --git a/internal/logging/framework.go b/internal/logging/framework.go
index eb3e8da..f704972 100644
--- a/internal/logging/framework.go
+++ b/internal/logging/framework.go
@@ -13,6 +13,8 @@ const (
// FrameworkDebug emits a framework subsystem log at DEBUG level.
func FrameworkDebug(ctx context.Context, msg string, additionalFields ...map[string]interface{}) {
+ return
+
tfsdklog.SubsystemDebug(ctx, SubsystemFramework, msg, additionalFields...)
}
@@ -23,6 +25,8 @@ func FrameworkError(ctx context.Context, msg string, additionalFields ...map[str
// FrameworkTrace emits a framework subsystem log at TRACE level.
func FrameworkTrace(ctx context.Context, msg string, additionalFields ...map[string]interface{}) {
+ return
+
tfsdklog.SubsystemTrace(ctx, SubsystemFramework, msg, additionalFields...)
}
```
### Terraform Configuration Files
I've got a big nested `entries` attribute on my resource that looks like this:
```
resource "incident_catalog_entries" "services" {
id = incident_catalog_type.service.id
entries = {
for _, entry in local.catalog :
# Map from our external ID => value for each of the attributes.
entry["id"] => {
name = entry["type_data"]["name"],
attribute_values = {
// lots of values here
}
}
}
}
```
I can share the provider but I think the only part that is probably relevant is the schema:
```go
func (r *IncidentCatalogEntriesResource) Schema(ctx context.Context, req resource.SchemaRequest, resp *resource.SchemaResponse) {
resp.Schema = schema.Schema{
MarkdownDescription: apischema.TagDocstring("Catalog V2"),
Attributes: map[string]schema.Attribute{
"id": schema.StringAttribute{
MarkdownDescription: apischema.Docstring("CatalogEntryV2ResponseBody", "catalog_type_id"),
PlanModifiers: []planmodifier.String{
stringplanmodifier.RequiresReplace(),
},
Required: true,
},
"entries": schema.MapNestedAttribute{
Required: true,
NestedObject: schema.NestedAttributeObject{
Attributes: map[string]schema.Attribute{
"id": schema.StringAttribute{
MarkdownDescription: apischema.Docstring("CatalogEntryV2ResponseBody", "id"),
Computed: true,
PlanModifiers: []planmodifier.String{
stringplanmodifier.UseStateForUnknown(),
},
},
"name": schema.StringAttribute{
MarkdownDescription: apischema.Docstring("CatalogEntryV2ResponseBody", "name"),
Required: true,
},
"alias": schema.StringAttribute{
MarkdownDescription: apischema.Docstring("CatalogEntryV2ResponseBody", "alias"),
Optional: true,
},
"rank": schema.Int64Attribute{
MarkdownDescription: apischema.Docstring("CatalogEntryV2ResponseBody", "rank"),
Optional: true,
Computed: true,
Default: int64default.StaticInt64(0),
},
"attribute_values": schema.MapNestedAttribute{
Required: true,
NestedObject: schema.NestedAttributeObject{
Attributes: map[string]schema.Attribute{
"value": schema.StringAttribute{
Description: `The value of this attribute, in a format suitable for this attribute type.`,
Optional: true,
},
"array_value": schema.ListAttribute{
ElementType: types.StringType,
Description: `The value of this element of the array, in a format suitable for this attribute type.`,
Optional: true,
},
},
},
},
},
},
},
},
}
}
```
### Debug Output
Debug and trace logs kinda are the problem here, so I'll point people at the top profile output.
### Expected Behavior
My plan executes in a normal time (<30s).
### Actual Behavior
My plan takes so long to execute that most people would give up (30s+, actually only finishes ~10m later).
### Steps to Reproduce
Build a highly nested object with many entries and attempt a plan.
### References
Not that I'm aware. I did search for `logging` and `performance` in this repo and a few others, but couldn't find anything.