Vscode-php-debug: Stuck and timeout when getting local variables after update to 1.9.5
VS Code version: 1.6.0
PHP version: PHP Version 5.6.25-2+deb.sury.org~xenial+1
XDebug version: Xdebug v2.4.1
Adapter version: PHP Debug 1.9.5
Your launch.json:
{
"version": "0.2.0",
"configurations": [
{
"name": "Listen for XDebug",
"type": "php",
"request": "launch",
"port": 9000,
"serverSourceRoot": "/srv/www/projectdir/",
"localSourceRoot": "${workspaceRoot}/",
},
{
"name": "Launch currently open script",
"type": "php",
"request": "launch",
"program": "${file}",
"cwd": "${fileDirname}",
"port": 9000
}
]
}
Developing on Windows while having the whole project as a _shared folder_ from Windows to a VirtualBox machine, inside which the LAMP stuff runs.
XDebug php.ini config:
[XDebug]
xdebug.profiler_enable_trigger=true
xdebug.profiler_output_dir='//srv/www/xdebug/'
xdebug.remote_log='//srv/www/xdebug/remote.log'
xdebug.remote_mode = req
xdebug.remote_enable=true
xdebug.remote_connect_back=true
xdebug.remote_port=9000
xdebug.var_display_max_depth=6
xdebug.var_display_max_children=512
xdebug.var_display_max_data=1024
XDebug logfile (from setting xdebug.remote_log in php.ini): _Too big to show._
Adapter logfile (from setting "log": true in launch.json):
<- launchResponse
Response {
seq: 0,
type: 'response',
request_seq: 2,
command: 'launch',
success: true }
new connection 1
<- threadEvent
ThreadEvent {
seq: 0,
type: 'event',
event: 'thread',
body: { reason: 'started', threadId: 1 } }
-> threadsRequest
{ command: 'threads', type: 'request', seq: 3 }
<- threadsResponse
Response {
seq: 0,
type: 'response',
request_seq: 3,
command: 'threads',
success: true,
body: { threads: [ Thread { id: 1, name: 'Request 1 (12:00:21)' } ] } }
<- initializedEvent
InitializedEvent { seq: 0, type: 'event', event: 'initialized' }
-> setBreakpointsRequest
{ command: 'setBreakpoints',
arguments:
{ source:
{ path: 'd:\\_Work\SomePath\FileWhatever.php',
name: 'SomeFile.php' },
lines: [],
breakpoints: [],
sourceModified: false },
type: 'request',
seq: 4 }
<- setBreakpointsResponse
Response {
seq: 0,
type: 'response',
request_seq: 4,
command: 'setBreakpoints',
success: true,
body: { breakpoints: [] } }
-> setBreakpointsRequest
{ command: 'setBreakpoints',
arguments:
{ source:
{ path: 'd:\\_Work\SomePath\FileWhatever.php',
name: 'SomeFile.php' },
lines: [],
breakpoints: [],
sourceModified: false },
type: 'request',
seq: 5 }
{ command: 'setBreakpoints',
arguments:
{ source:
{ path: 'd:\\_Work\SomePath\FileWhatever.php',
name: 'SomeFile.php' },
lines: [ 189 ],
breakpoints: [ { line: 189 } ],
sourceModified: false },
type: 'request',
seq: 6 }
-> setFunctionBreakpointsRequest
{ command: 'setFunctionBreakpoints',
arguments: { breakpoints: [] },
type: 'request',
seq: 10 }
<- setFunctionBreakpointsResponse
Response {
seq: 0,
type: 'response',
request_seq: 10,
command: 'setFunctionBreakpoints',
success: true,
body: { breakpoints: [] } }
-> setExceptionBreakpointsRequest
{ command: 'setExceptionBreakpoints',
arguments: { filters: [] },
type: 'request',
seq: 11 }
<- setExceptionBreakpointsResponse
Response {
seq: 0,
type: 'response',
request_seq: 11,
command: 'setExceptionBreakpoints',
success: true }
-> configurationDoneRequest
{ command: 'configurationDone', type: 'request', seq: 12 }
<- configurationDoneResponse
Response {
seq: 0,
type: 'response',
request_seq: 12,
command: 'configurationDone',
success: true }
<- stoppedEvent
StoppedEvent {
seq: 0,
type: 'event',
event: 'stopped',
body: { reason: 'breakpoint', threadId: 1, allThreadsStopped: false } }
-> threadsRequest
{ command: 'threads', type: 'request', seq: 13 }
<- threadsResponse
Response {
seq: 0,
type: 'response',
request_seq: 13,
command: 'threads',
success: true,
body: { threads: [ Thread { id: 1, name: 'Request 1 (12:00:21)' } ] } }
-> stackTraceRequest
{ command: 'stackTrace',
arguments: { threadId: 1, startFrame: 0, levels: 20 },
type: 'request',
seq: 14 }
<- stackTraceResponse
Response {
seq: 0,
type: 'response',
request_seq: 14,
command: 'stackTrace',
success: true,
body:
{ stackFrames:
[ StackFrame {
id: 1,
source:
Source {
name: 'SomeFile.php',
path: 'd:\\_Work\SomePath\FileWhatever.php',
sourceReference: 0 },
line: 128,
column: 1,
name: 'SomeObject->wakeUp' },
StackFrame {
id: 2,
source:
Source {
name: 'SomeFile.php',
path: 'd:\\_Work\SomePath\FileWhatever.php',
sourceReference: 0 },
line: 74,
column: 1,
name: 'SomeObject->startup' },
StackFrame {
id: 3,
source:
Source {
name: 'SomeFile.php',
path: 'd:\\_Work\SomePath\FileWhatever.php',
sourceReference: 0 },
line: 15,
column: 1,
name: 'SomeObject->startup' },
StackFrame {
id: 4,
source:
Source {
name: 'SomeFile.php',
path: 'd:\\_Work\SomePath\FileWhatever.php',
sourceReference: 0 },
line: 168,
column: 1,
name: 'SomeObject->run' },
StackFrame {
id: 5,
source:
Source {
name: 'SomeFile.php',
path: 'd:\\_Work\SomePath\FileWhatever.php',
sourceReference: 0 },
line: 124,
column: 1,
name: 'SomeObject->run' },
StackFrame {
id: 6,
source:
Source {
name: 'index.php',
path: 'd:\\_Work\\SomePath\index.php',
sourceReference: 0 },
line: 10,
column: 1,
name: '{main}' } ] } }
-> scopesRequest
{ command: 'scopes',
arguments: { frameId: 1 },
type: 'request',
seq: 15 }
-> evaluateRequest
{ command: 'evaluate',
arguments: { expression: '$this', frameId: 1, context: 'watch' },
type: 'request',
seq: 16 }
<- scopesResponse
Response {
seq: 0,
type: 'response',
request_seq: 15,
command: 'scopes',
success: true,
body:
{ scopes:
[ Scope { name: 'Locals', variablesReference: 1, expensive: false },
Scope { name: 'Superglobals', variablesReference: 2, expensive: false },
Scope {
name: 'User defined constants',
variablesReference: 3,
expensive: false } ] } }
-> variablesRequest
{ command: 'variables',
arguments: { variablesReference: 1, filter: 'indexed' },
type: 'request',
seq: 17 }
[... waiting 9 seconds ...]
<- evaluateResponse
Response {
seq: 0,
type: 'response',
request_seq: 16,
command: 'evaluate',
success: true,
body:
{ result: 'SomeModule\\SomeManager',
variablesReference: 4 } }
[... waiting another 20 seconds ...]
<- variablesResponse
Response {
seq: 0,
type: 'response',
request_seq: 17,
command: 'variables',
success: true,
body:
{ variables:
[ { name: '$audit',
value: 'Lib\\Model\\DatabaseRow',
type: 'object',
variablesReference: 5 },
{ name: '$id',
value: 'uninitialized',
type: 'uninitialized',
variablesReference: 0 },
{ name: '$localAudit',
value: 'uninitialized',
type: 'uninitialized',
variablesReference: 0 },
{ name: '$remoteAudit',
value: 'uninitialized',
type: 'uninitialized',
variablesReference: 0 },
{ name: '$stats',
value: 'uninitialized',
type: 'uninitialized',
variablesReference: 0 },
{ name: '$this',
value: 'SomeModule\\SomeManager',
type: 'object',
variablesReference: 6 } ] } }
Code snippet to reproduce:
<a large project with two thousands of PHP files>
I don't know how the previous versions of this extensions were handling it, but it seems that for each step of the code it pulls a lot, a lot of data, when it's trying to get local variables:
And eventually _(after a few step-overs)_ it ends up like this:
The _XDebug_'s remote.log file, when only one breakpoint is introduced, grows to a 117 MB large log, most of it being stuff like:
<response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="http://xdebug.org/dbgp/xdebug" command="eval" transaction_id="19"><property type="object" classname="Module\FooManager" children="1" numchildren="12" page="0" pagesize="10000"><property name="client" facet="protected" type="object" classname="Api\FooClient" children="1" numchildren="11" page="0" pagesize="10000"><property name="userAgent" facet="public" type="string" size="7" encoding="base64"><![CDATA[TWVyZ2Fkbw==]]></property><property name="disableSslVerification" facet="public" type="bool"><![CDATA[0]]></property><property name="disableSslHostnameVerification" facet="public" type="bool"><![CDATA[0]]></property><property name="requestRetries" facet="public" type="int"><![CDATA[2]]></property><property name="retryInterval" facet="public" type="int"><![CDATA[2]]></property><property name="server" facet="protected" type="string" size="27" encoding="base64"><![CDATA[aHR0cHM6Ly94LW0zZGV2Lm1lcmdhZG8uY29t]]></property><property name="options" facet="protected" type="null"></property><property name="username" facet="protected" type="string" size="3" encoding="base64"><![CDATA[YXBp]]></property><property name="password" facet="protected" type="string" size="8" encoding="base64"><![CDATA[bmFNRXN0NTc=]]></property><property name="certificateFile" facet="protected" type="null"></property><property name="curl" facet="protected" type="resource"><![CDATA[resource id='214' type='curl']]></property></property><property name="model" facet="protected" type="object" classname="Module\FooModel" children="1" numchildren="12" page="0" pagesize="10000"><property name="entities" facet="static protected" type="array" children="0" numchildren="0" page="0" pagesize="10000"></propert
[...] (and it goes on and on)
It may be that my _XDebug_ settings are too megalomaniac (are they?):
xdebug.var_display_max_depth=6
xdebug.var_display_max_children=512
xdebug.var_display_max_data=1024
But the previous version did not behave like this and obtaining data about local variables was brisk.
Was it that the previous version was not doing things (obtaining variables) correctly and this one now is, and that's what's causing it?
Or is it the other way around?
_Am I alone in this? :)_
bug
smuuf
👍1
All 10 comments
I can confirm this is as a bug but I don't know the cause, the test suite didn't catch this. I don't have time atm to look into this. I recommend you downgrade to 1.9.4: https://github.com/felixfbecker/vscode-php-debug/releases/tag/v1.9.4
felixfbecker
on 12 Oct 2016
❤1
The xdebug log file would still help though if you could upload it
felixfbecker
on 12 Oct 2016
Ah, thank you. I was looking for some downgrade options :)
Also I tried to downscale a bit the _XDebug_ config numbers to:
[XDebug]
xdebug.profiler_enable_trigger=true
xdebug.profiler_output_dir='//srv/www/xdebug/'
xdebug.remote_mode = req
xdebug.remote_enable=true
xdebug.remote_connect_back=true
xdebug.remote_port=9000
xdebug.var_display_max_depth=3
xdebug.var_display_max_children=128
xdebug.var_display_max_data=512
But it still took about 17 seconds to load info about locals.
smuuf
on 12 Oct 2016
No, it clearly is a bug. Sorry for breaking your tools
felixfbecker
on 12 Oct 2016
Maybe you could test #65?
felixfbecker
on 12 Oct 2016
Seems like changing those numbers did the job. Now it's lightning fast. Great! :)
yield connection.sendFeatureSetCommand('max_depth', '3');
yield connection.sendFeatureSetCommand('max_children', '100');
yield connection.sendFeatureSetCommand('max_data', semver.lt(initPacket.engineVersion.replace(/((?:dev|alpha|beta|RC|stable)\d*)$/, '-$1'), '2.2.4') ? '1000' : '0');
👍1
Although when I download the new 1.9.6 version I noticed you'd put on Marketplace, I still see:
yield connection.sendFeatureSetCommand('max_depth', '10');
yield connection.sendFeatureSetCommand('max_children', '10000');
yield connection.sendFeatureSetCommand('max_data', semver.lt(initPacket.engineVersion.replace(/((?:dev|alpha|beta|RC|stable)\d*)$/, '-$1'), '2.2.4') ? '10000' : '0');
in the .vscode\extensions\felixfbecker.php-debug-1.9.6\out\phpDebug.js.
:)
smuuf
on 12 Oct 2016
1.9.6 doesnt contain the fix, the PR is not merged...
felixfbecker
on 12 Oct 2016
Fixed in 1.9.7
felixfbecker
on 12 Oct 2016
That's awesome. Thank you so much. :)
smuuf
on 13 Oct 2016
Was this page helpful?
0 / 5 - 0 ratings
Related issues
herbertpimentel
路
6Comments
eghoff1
路
10Comments
camrongodbout
路
5Comments
johnbillion
路
6Comments
PipCodeBoy
路
5Comments