Analysing an existing v8.log

Jun 16, 2014 at 6:09 AM
Edited Jun 16, 2014 at 6:10 AM
Hi
just checked out your profiler , really neat stuff.
My question is . Can I use your profiler just to analysis and existing v8.log file.
For different reasons , I prefer to run my application seperately (not from within vs) with --prof and other flags set . and after the v8.log is created then I really would love to load it in your cool UI for analysis.
One example is that my customer can run the app and then send me the v8.log
Is that possible. ? If not , I think its a killer feature which you should have no problem to add .

Thanks.
Coordinator
Jun 17, 2014 at 4:50 PM
Hi rino65,

Please have a look at Microsoft.NodejsTools.NodeLogConverter.exe. It should be located in the "Node.js Tools - Profiling\1.0" folder. This is what we use in the product, you can see how we invoke it from here: https://nodejstools.codeplex.com/SourceControl/latest#Nodejs/Product/Profiling/Profiling/ProfiledProcess.cs
Jun 18, 2014 at 6:39 AM
Edited Jun 18, 2014 at 6:52 AM
Hi
Thanks for the reply. I couldnt quite get the command line parameters.
I have a v8.log in c:\temp
I wrote
Microsoft.NodejsTools.NodeLogConverter.exe /jmc c:\temp c:\temp

I got an exception access denied for some reason . the directory is writable for sure.

Unhandled Exception: System.UnauthorizedAccessException: Access to the path 'c:\temp' is denied.
at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
at System.IO.FileStream.Init(String path, FileMode mode, FileAccess access, Int32 rights, Boolean useRights, FileShar
e share, Int32 bufferSize, FileOptions options, SECURITY_ATTRIBUTES secAttrs, String msgPath, Boolean bFromProxy, Boolea
n useLongPath, Boolean checkHost)
at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileO
ptions options, String msgPath, Boolean bFromProxy, Boolean useLongPath, Boolean checkHost)
at System.IO.StreamReader..ctor(String path, Encoding encoding, Boolean detectEncodingFromByteOrderMarks, Int32 buffe
rSize, Boolean checkHost)
at System.IO.StreamReader..ctor(String path)
at Microsoft.NodejsTools.LogParsing.LogConverter.CreatePdbFile(Guid& pdbSig, UInt32& pdbAge)
at Microsoft.NodejsTools.LogParsing.LogConverter.Process()
at Microsoft.NodejsTools.LogParsing.LogConverter.Main(String[] args)


Also , Please explain what should be done after that .
Lets saw we fix the command line parameters and get a vspx file ,what do I do with it ? How do I open it in visual studio ?
Thanks.
Coordinator
Jun 18, 2014 at 5:32 PM
It's expecting file paths, not folder paths. Try running it without params, you'll get some help text. I would expect you'd be able to drag & drop the .vspx file from explorer into VS.
Jun 22, 2014 at 6:47 AM
Hi
I put paths and it seemed to be doing something , but then I got and exception.
Unhandled Exception: System.InvalidOperationException: Nullable object must have a value.
at System.ThrowHelper.ThrowInvalidOperationException(ExceptionResource resource)
at System.Nullable`1.get_Value()
at Microsoft.NodejsTools.LogParsing.LogConverter.Process()
at Microsoft.NodejsTools.LogParsing.LogConverter.Main(String[] args)

It created an etl file but when I dragged it to VS it opened the Windows Performance Analyser but it didnt give much information. just a few cpu benchmarks no function or anything.

Unfortuantely I cant add the v8.log as attachement to this reply but its a very simple one and Im sure it will happen in all of them
Jun 23, 2014 at 8:19 AM
Hi Again
Some advancement
After a little stack trace debugging I saw that I have to add the two other parameters start time and execution time
what do I need this for , isnt this information part of the v8.log .
I just chose a few numbers randomy start time 0 execution time 30
I got a vspx and dragged it into VS . It took A VERY LONG TIME till I got the graphs and views but I did get it finally.

So my questions are
  1. if I have v8.log , why do I need to give it the start time and execution time ?
  2. what exactly are they used for , and what is the best solution for me assuming I have no idea what the start time was and what the execution time was. From the code I see that the LogConverter doesnt even look at the start time , only at the execution time
Thanks.
Coordinator
Jun 23, 2014 at 7:01 PM
You're right that the start time is no longer used and can be removed. The execution time is used to update the ETL file so that the stacks are generated with the correct timestamps. After generating the ETL file using the normal APIs we use an API introduced in Windows 8 which allows us to re-write the file with new time stamps (because when it's generated it gets generated with the timestamps of the log converter process). This ultimately makes the graph which VS displays for activity work correctly so that you can see spikes and dips in CPU usage overtime. Without doing this the graph just appears to be a straight line. Unfortunately there are no time stamps in the generated v8.log AFAICT - there is just a list of ticks with their associated stack trace.
Jun 24, 2014 at 5:37 AM
Hi dinov
thanks for the reply
so my question is , what do I do with an existing v8 log when I dont know the execution time. ? is there any way around this ?

BTW isnt it possible to find this information somehow in the v8.log by anlyzing the ticks.?

Thanks.
Jun 25, 2014 at 4:42 AM
Hi Again

From another look and some tests I see that the execution time is only for the cpu usage graph . is this true ? It does not effect the function profiling tables inclusive exclusive etc.
Can someone confirm this please.
Thanks.
Coordinator
Jun 25, 2014 at 5:37 AM
That's correct, it's only the graph. You should be able to omit it from the command line and a slightly less useful profile is generated.
Jun 25, 2014 at 6:20 AM
great
thanks.
Jul 22, 2014 at 3:47 PM
Hi,

Is there a way to analyze an existing v8.log which was created on Linux?
Coordinator
Jul 22, 2014 at 4:38 PM
Have you tried running NodeLogConverter.exe on it? I would expect it to just work, unless the Linux log is somehow significantly different from the Windows one.
Jul 23, 2014 at 2:35 PM
Edited Jul 23, 2014 at 2:36 PM
Yes, I have tried that.
Specifically tried on debian.
Coordinator
Jul 23, 2014 at 4:49 PM
Can you tell more about the problems that you've ran into?
Jul 24, 2014 at 8:31 AM
Opened up the performance explorer loaded up the .vspx file but it shows me these messages:
  1. Warning VSP2702: Report does not have required information to resolve source lines in functions for process ‘node.exe’. This is expected for managed applications that target Framework 2.0-3.5.
  2. No call tree data is available
Jul 28, 2014 at 2:06 PM
Are you able to reproduce the problem?
Coordinator
Jul 28, 2014 at 8:40 PM
I've got a repro, sort of.

The warning is spurious - you will see it when using the profiler in the normal way, as well. Unfortunately, it's a silly check that VS always does that is completely irrelevant for Node.js (and Python).

Regarding no call tree data at all, you'll get this if you specify 0 as the last command-line argument to LogConverter, regardless of the source of data. Basically, it looks like it needs to be some non-zero value, and it must be in CLR TimeSpan format ([-][d.]hh:mm:ss[.fffffff]).

With that, you do get a call tree, but it's all "unknown". I'll look into what's going on there.
Coordinator
Jul 28, 2014 at 8:53 PM
I don't see anything suspicious in the way we handle the log in this case. It seems that VS doesn't like the output. One suspicion that I have is that when the Node process is 64-bit, Windows and Linux use different ABIs for that. Since v8.log reports ticks as stack walks with instruction pointers, I wonder if they don't carry over due to ABI difference...
Jul 31, 2014 at 1:01 PM
I hope this get fixed soon. Really looking forward using this tool.
Coordinator
Aug 12, 2014 at 5:23 PM
This discussion has been copied to a work item. Click here to go to the work item and continue the discussion.