Validation lag leading to state issues, particularly in long/complex models

[anikaks]

This is a bit tricky to reproduce, but we had a report of a file taking 30-60 seconds to validate when changes are made. This results in functioning queries sometimes showing up with red error squiggles while it validates. One thing to investigate is that it seems to be happening in particular in a file with extensive alternation operator use; just one example had 50 | separated values in a where on a source.

[anikaks]

reported by @doit-mattporter

[gmaden]

Have you tried enabling tracing for the language server to see if we can narrow down which language server call might be causing this issue?

In settings.json for add the option: "malloy.trace.server": "verbose"

Then in the output for the language server it should include way too much information, but in particular the "Received response" lines should include some information on what the request was and how long the response took.

[anikaks]

Current update is that the red squiggles issue is dormant for now (yay!).

But there still seems to be an issue with validation lag--the latest symptom for @doit-mattporter is that if a query is renamed and then run, an error of Cannot read properties of undefined (reading 'type') is returned. The window for this seems to be a few seconds, yet he is seeing relatively fast times in the logs:

[Trace - 3:25:45 PM] Received response 'textDocument/codeLens - (105)' in 11ms.
[Trace - 3:25:45 PM] Received response 'textDocument/documentSymbol - (107)' in 11ms.

Interestingly when I test the rename and immediately run in a simple model, I get an error too but it's a different one and I don't know why, we're both running v0.3.1668022128 :

Error(s) compiling model:
FILE: internal://internal.malloy
line 1: 'top_brands' is not defined
  | query: product->top_brands
  |        ^
line 1: Query 'top_brands' is not defined in source
  | query: product->top_brands
  |        ^

in this case I renamed a query from top_brands to topbrands; it seems the model validated faster than the code lens or something like that?

My language server logs for this show things taking only a couple ms. I'm fast but I'm not 3ms fast, so something is taking longer than these logs indicate...

[Trace - 3:57:49 PM] Sending notification 'textDocument/didChange'.
Params: {
    "textDocument": {
        "uri": "file:///Users/anikaks/Desktop/slow_validation_repro/products.malloy",
        "version": 207
    },
    "contentChanges": [
        {
            "range": {
                "start": {
                    "line": 5,
                    "character": 12
                },
                "end": {
                    "line": 5,
                    "character": 13
                }
            },
            "rangeLength": 1,
            "text": ""
        }
    ]
}

[Trace - 3:57:49 PM] Received notification 'textDocument/publishDiagnostics'.
Params: {
    "uri": "file:///Users/anikaks/Desktop/slow_validation_repro/products.malloy",
    "diagnostics": [],
    "version": 207
}

[Trace - 3:57:49 PM] Sending request 'textDocument/codeLens - (956)'.
Params: {
    "textDocument": {
        "uri": "file:///Users/anikaks/Desktop/slow_validation_repro/products.malloy"
    }
}

[Trace - 3:57:49 PM] Received response 'textDocument/codeLens - (956)' in 1ms.
Result: [
    {
        "range": {
            "start": {
                "line": 0,
                "character": 8
            },
            "end": {
                "line": 8,
                "character": 5
            }
        },
        "command": {
            "title": "Preview",
            "command": "malloy.runQuery",
            "arguments": [
                "query: product->{ project: *; limit: 20 }",
                "preview product"
            ]
        }
    },
    {
        "range": {
            "start": {
                "line": 5,
                "character": 9
            },
            "end": {
                "line": 8,
                "character": 3
            }
        },
        "command": {
            "title": "Run",
            "command": "malloy.runQuery",
            "arguments": [
                "query: product->topbrands",
                "product->topbrands"
            ]
        }
    }
]

[Trace - 3:57:49 PM] Sending request 'textDocument/semanticTokens/full - (957)'.
Params: {
    "textDocument": {
        "uri": "file:///Users/anikaks/Desktop/slow_validation_repro/products.malloy"
    }
}

[Trace - 3:57:49 PM] Received response 'textDocument/semanticTokens/full - (957)' in 0ms.
Result: {
    "resultId": "1668038269424",
    "data": []
}

[Trace - 3:57:49 PM] Sending request 'textDocument/documentSymbol - (958)'.
Params: {
    "textDocument": {
        "uri": "file:///Users/anikaks/Desktop/slow_validation_repro/products.malloy"
    }
}

[Trace - 3:57:49 PM] Received response 'textDocument/documentSymbol - (958)' in 1ms.
Result: [
    {
        "name": "product",
        "range": {
            "start": {
                "line": 0,
                "character": 8
            },
            "end": {
                "line": 8,
                "character": 5
            }
        },
        "detail": "explore",
        "kind": 3,
        "selectionRange": {
            "start": {
                "line": 0,
                "character": 8
            },
            "end": {
                "line": 8,
                "character": 5
            }
        },
        "children": [
            {
                "name": "product_count",
                "range": {
                    "start": {
                        "line": 1,
                        "character": 11
                    },
                    "end": {
                        "line": 1,
                        "character": 35
                    }
                },
                "detail": "field",
                "kind": 8,
                "selectionRange": {
                    "start": {
                        "line": 1,
                        "character": 11
                    },
                    "end": {
                        "line": 1,
                        "character": 35
                    }
                },
                "children": []
            },
            {
                "name": "topbrands",
                "range": {
                    "start": {
                        "line": 5,
                        "character": 9
                    },
                    "end": {
                        "line": 8,
                        "character": 3
                    }
                },
                "detail": "query",
                "kind": 5,
                "selectionRange": {
                    "start": {
                        "line": 5,
                        "character": 9
                    },
                    "end": {
                        "line": 8,
                        "character": 3
                    }
                },
                "children": [
                    {
                        "name": "brand",
                        "range": {
                            "start": {
                                "line": 6,
                                "character": 14
                            },
                            "end": {
                                "line": 6,
                                "character": 19
                            }
                        },
                        "detail": "field",
                        "kind": 8,
                        "selectionRange": {
                            "start": {
                                "line": 6,
                                "character": 14
                            },
                            "end": {
                                "line": 6,
                                "character": 19
                            }
                        },
                        "children": []
                    }
                ]
            }
        ]
    }
]

[anikaks]

OK solved that. The error I got above occurs when the source is implicit (i.e. the query is defined under the source). Cannot read properties of undefined (reading 'type') occurs when the query is named outside a source.

In this example, a quick rename-then-run of either inner_test or outer_test return the two different errors.

source: order_items is table('malloy-data.ecomm.order_items'){
  measure: oi_count is count()

  query: inner_test is {
    group_by: status
    aggregate: oi_count
  }
}

query: outer_test is order_items -> {
  group_by: deliver_month is delivered_at.month
  aggregate: oi_count
}

[anikaks]

One final data point, it seems that longer and more complex models have a longer lag between renaming and being able to run the query. Which just tells us that longer and more complex models take longer to validate--not shocking--so the time in the mismatched state is drawn out.

[anikaks]

Sounds like this has reared its head today after taking a break from causing trouble for a while. Long pick statements (several hundred values of a field mapped to a smaller set of values) seems to be the culprit. Anything importing the file with the pick statement is affected, to the tune of 20+ second validation lags. Force quitting VS Code, it validates instantly when reopend.