vscode-php-debug icon indicating copy to clipboard operation
vscode-php-debug copied to clipboard

While debugging, hover tooltip takes 3 seconds to show

Open GeeZuZz opened this issue 3 years ago • 10 comments

PHP version: 8.0.6 Xdebug version: v3.0.4 VS Code extension version: v1.23.0

  • Using PHP and xDebug
  • Put a breakpoint
  • Press F5 to enter debugging
  • Wait for VS code to break at the breakpoint
  • While stopped at a breakpoint. hover over a variable in the code
  • I have to wait an excessively long time (about 3 seconds) before the tooltip with variable info shows up.

I expect the hover tooltip show up more quickly, or behave according to the setting "Editor › Hover: Delay". Changing this setting does not make any difference.

Important: This bug has been introduced in a release the past few months. I have two identically setup PCs, where one hasn't been updated in a while. While trying to confirm the bug, I tested it on the old PC, but there I couldn't recreate it (tooltip showed up quickly, like expected). Then I updated VS Code to latest version on that machine also, and now that PC also have the issue with delayed tooltip (3 seconds). I don't know how to see which version it had before I updated.

GeeZuZz avatar Feb 06 '22 21:02 GeeZuZz

Hi. Indeed there were some changes in this area. You can install an older version of the plugin in the Extensions side bar. Can you try it with an older version. And please collect a debug log from debug console.

zobo avatar Feb 06 '22 22:02 zobo

I tried installing v1.2.2, but it doesn't work, it just uninstalls it when I select that version. No errors. Tried one of the very old version, but was prompted to reload VS Code, and after reloading, for some reason the latest version was installed again.

GeeZuZz avatar Feb 07 '22 13:02 GeeZuZz

Ah yes. We migrated the extension to a new publisher, so thats probably not possible. Can you try to produce the log instead? Add log: true to your launch.json an then attach the contents of the Debug Console.

zobo avatar Feb 07 '22 13:02 zobo

I think this is the relevant part from the log:

-> evaluateRequest
{
  command: 'evaluate',
  arguments: { expression: '$database', frameId: 1, context: 'hover' },
  type: 'request',
  seq: 17
}
xd(1) <- context_names -i 12 -d 0
xd(1) -> <?xml version="1.0" encoding="iso-8859-1"?><response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="context_names" transaction_id="12"><context name="Locals" id="0"></context><context name="Superglobals" id="1"></context><context name="User defined constants" id="2"></context></response>
xd(1) <- property_get -i 13 -d 0 -c 0 -n "$database"
xd(1) -> <?xml version="1.0" encoding="iso-8859-1"?><response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="property_get" transaction_id="13" status="break" reason="ok"><error code="300"><message><![CDATA[can not get property]]></message></error></response>
<- evaluateResponse
Response {
  seq: 0,
  type: 'response',
  request_seq: 17,
  command: 'evaluate',
  success: false,
  message: 'can not get property'
}

Just need to point out that it does WORK, e.g variable info shows up eventually, it just takes 3 seconds.

GeeZuZz avatar Feb 07 '22 14:02 GeeZuZz

Interesting, since this par of the log says it cannot fetch $database. Is that a global or some other special variable? Ate you at the top of the stack or somewhere deeper? Sadly I do not print timestamps with the logs, but how does this relate to when the hover does show up?

zobo avatar Feb 07 '22 14:02 zobo

I cleared the log before hover, and this is what shows up in the log when I hover. $database is just a normal variable in my code.

Here is the console output after hovering these two variables in the code:

$testvar1 = "variable-value1"; $testvar2 = "variable-value2";

-> evaluateRequest
{
  command: 'evaluate',
  arguments: { expression: '$testvar1', frameId: 2, context: 'hover' },
  type: 'request',
  seq: 25
}
xd(2) <- context_names -i 12 -d 0
xd(2) -> <?xml version="1.0" encoding="iso-8859-1"?><response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="context_names" transaction_id="12"><context name="Locals" id="0"></context><context name="Superglobals" id="1"></context><context name="User defined constants" id="2"></context></response>
xd(2) <- property_get -i 13 -d 0 -c 0 -n "$testvar1"
xd(2) -> <?xml version="1.0" encoding="iso-8859-1"?><response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="property_get" transaction_id="13"><property name="$testvar1" fullname="$testvar1" type="string" size="15" encoding="base64"><![CDATA[dmFyaWFibGUtdmFsdWUx]]></property></response>
<- evaluateResponse
Response {
  seq: 0,
  type: 'response',
  request_seq: 25,
  command: 'evaluate',
  success: true,
  body: { result: '"variable-value1"', variablesReference: 0 }
}
-> evaluateRequest
{
  command: 'evaluate',
  arguments: { expression: '$testvar2', frameId: 2, context: 'hover' },
  type: 'request',
  seq: 26
}
xd(2) <- context_names -i 14 -d 0
xd(2) -> <?xml version="1.0" encoding="iso-8859-1"?><response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="context_names" transaction_id="14"><context name="Locals" id="0"></context><context name="Superglobals" id="1"></context><context name="User defined constants" id="2"></context></response>
xd(2) <- property_get -i 15 -d 0 -c 0 -n "$testvar2"
xd(2) -> <?xml version="1.0" encoding="iso-8859-1"?><response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="property_get" transaction_id="15"><property name="$testvar2" fullname="$testvar2" type="string" size="15" encoding="base64"><![CDATA[dmFyaWFibGUtdmFsdWUy]]></property></response>
<- evaluateResponse
Response {
  seq: 0,
  type: 'response',
  request_seq: 26,
  command: 'evaluate',
  success: true,
  body: { result: '"variable-value2"', variablesReference: 0 }
}

GeeZuZz avatar Feb 07 '22 14:02 GeeZuZz

There two have positive responses... Do they also take 3 seconds? Do they show up the same time the evaluateResponse is logged?

zobo avatar Feb 07 '22 14:02 zobo

Yes, for both variables, it takes 3 seconds of hover, then the tooltip shows up, and the text appears in the log. Nothing shows in the log when I start the hover - only when the tooltip shows up after 3 seconds of hovering.

Edit: I just now noticed that my first log ($database) showed an error in the log, while the last ones did not. I think maybe the first log I posted should be ignored, since that error probably was unrelated.

GeeZuZz avatar Feb 07 '22 14:02 GeeZuZz

Ok, so the delay could come in before hovering is triggered. Maybe in the extension https://code.visualstudio.com/api/references/vscode-api#EvaluatableExpression ...

I'll try to reproduce it here, but I have not yet seen a case. Could be a conflict with some other extension. Do you have any other PHP related extensions installed?

zobo avatar Feb 07 '22 14:02 zobo

This is a bit strange - I somehow got it working on my main machine (at least, the hover time only takes 1 second now). But on my other machine, the problem is still there, when breaking in the exact same file. That computer only has xdebug and "PHP Intelephense v1.8.0" extensions installed.

I won't be able to troubleshoot any more today, but since I got it working again on one computer, this might be some configuration issue, so I guess you should wait for further info before you look more into it. Thanks for all help!

GeeZuZz avatar Feb 07 '22 15:02 GeeZuZz

Quite old this task, I'll close it and if it had some recent development please make a new one.

zobo avatar Jul 28 '23 14:07 zobo