Re: Advanced Diagnostics with the MivaScript debug log
It sounds like you weren't editing the correct configuration file. If your site is hosted with us you can open a support ticket and we can get to the bottom of things.
Announcement
Collapse
No announcement yet.
Advanced Diagnostics with the MivaScript debug log
Collapse
X
-
Re: Advanced Diagnostics with the MivaScript debug log
I am having three problems getting mvprof to work. I am on engine 5.19.
1. In the cgi-bin folder I do not see a .conf file. I do have a miva.conf file. Is that where I add:
logfile=mvconfOutput.logloglevel=144
logcookie=somecookievalue
2. Also having problem getting the shell terminal to work through plesk. It does not accept my password.
3. The diagtool.mvc says the logcookie is not set at the engine level.
I can set a cookie on my browser through firebug. I've rolled back everything for now and removed diagtool.mvc.
Leave a comment:
-
Re: Advanced Diagnostics with the MivaScript debug log
Originally posted by Bruce - PhosphorMedia View PostBut how would you parse the log file? It seemed (from the instructions) that the two parsing routines where built into the engine?
Leave a comment:
-
Re: Advanced Diagnostics with the MivaScript debug log
But how would you parse the log file? It seemed (from the instructions) that the two parsing routines where built into the engine?
Leave a comment:
-
Re: Advanced Diagnostics with the MivaScript debug log
Originally posted by Bruce - PhosphorMedia View PostWe do a lot of performance tweaking for sites and this could be very helpful, but getting Shell access isn't going to be easy in manny cases. Any chanced that these features could be accessed through functionality in the admin (i.e., custom module)
Leave a comment:
-
Re: Advanced Diagnostics with the MivaScript debug log
We do a lot of performance tweaking for sites and this could be very helpful, but getting Shell access isn't going to be easy in manny cases. Any chanced that these features could be accessed through functionality in the admin (i.e., custom module)
Leave a comment:
-
Re: Advanced Diagnostics with the MivaScript debug log
Originally posted by burch View Postlogcookie=<any value you desire, should only contain letters and numbers>
Leave a comment:
-
Re: Advanced Diagnostics with the MivaScript debug log
We've released 5.18 from development and it should be available shortly. I also updated comment #5 to include a screenshot of the relevant sections of diagtool and added a link to our Knowledge Base article where you can download the tool.
Leave a comment:
-
Re: Advanced Diagnostics with the MivaScript debug log
that is GREAT, thank you again! I'll definitely take your advice and wait for 5.18
Leave a comment:
-
Re: Advanced Diagnostics with the MivaScript debug log
First, the log cookie is not available in the currently released engine. It requires 5.18, which should be released early next week. I highly recommend you wait until you are able to upgrade to 5.18 to attempt to do any profiling of live sites because without the log cookie setting ALL requests to your site will be logged as soon as you enable the debug log. If you have a high volume site this could result in hundreds of megabytes of log data being generated.
The following instructions assume you have heeded my warning and have your site running 5.18. If you want to live dangerously and try it on your current engine, just ignore anything having to do with the cookie:
1. If you have a .conf file in the cgi-bin directory, you're using the 3.x configuration. You would add the following lines to the file:
logfile=mvconfOutput.log
loglevel=144
logcookie=<any value you desire, should only contain letters and numbers>
Once those lines are added to the config file, logging is enabled. If you were on a version that does not support logcookie, the log file would start growing on the very next request to your site.
2. Use diagtool.mvc to cookie your browser with the appropriate cookie value by clicking on the "Log Cookie Status" link on the left, then "Set Log Cookie". If everything worked it should look like this:
Screenshot from 2013-03-20 10:29.jpg
diagtool.mvc is included with the 5.18 engine distribution or may be obtained from our Knowledge Base.
3. Make whatever hits to your site you want to profile.
4. Disable logging, either by removing the lines from your config file or by commenting them out (add the character "#" at the beginning of the line). I recommend doing this even if you are using logcookie.
5. Download the log file to your local PC. It will be in your mivadata directory.
6. Start a command prompt and run mvprof on the log file. You can use -o <outfile> to store the output in a text file (otherwise it is printed directly to the terminal).
Leave a comment:
-
Re: mvprof
This sounds great, thank you for all the info!
I'd like to use mvconf to an analyze our live site. I have SSH access to our server, but beyond that I'm not confident in what to do next. Can you confirm if these steps are even in the right ballpark?
- Enable logging: set the proper environment variables (in the cgi-bin conf file?):
- MvCONFIG_LOG_FILE (give it a filename like mvconfOutput.log for example)
- MvCONFIG_LOG_LEVEL - I'm not sure what level corresponds to a page load?
- MvCONFIG_LOG_COOKIE - not sure how to configure this cookie
- Generate a log file: this should be automatic based on the description?
- Run mvprof: will it know to use the mvconfOutput.log I set up in step 1?
Leave a comment:
- Enable logging: set the proper environment variables (in the cgi-bin conf file?):
-
mvprof
mvprof is a profiling tool that can be used to visualize and troubleshoot the performance of MivaScript programs. When applied to Miva Merchant, it is extremely useful to diagnose slow loading pages and other odd performance problems.
Like mvcov, it is a command line tool that has been bundled with the compiler distribution since v5.16 and will output a description of its parameters when run with --help:
Code:Usage: mvprof [options] logfile Options: --help Display this information --version Display version number and exit -p <pid> Include only log lines from the specified process_id -f <filename> Generate profile output only for compiled file <filename> (may repeat) -o <output> Write output to <output> -M Profile MivaScript functions only -B Profile builtin functions only -F Output flat profile only (suppress call graph) -G Output call graph only (suppress flat profile)
Using mvprof
1. Enable logging: mvprof requires a log containing function call and return data to generate its output. In most cases, MivaScript functions are the ones you will be interested in profiling, so on Windows you would enable the MivaScript "Function Call" and "Function Return" options, or on UNIX would use a log level of 144. It is possible to include profiling of builtin functions as well, but you need to be careful about introducing a time bias into the profile by generating an extremely large log file.
2. Generate a log file: After configuring logging, any requests made to the site being debugged will result in those requests being logged to the debug log. It is strongly recommended that you only attempt to capture a profile log on a live site using the 5.18 engine and the new log cookie mechanism.
3. Run mvprof: mvprof does not require any source code. Once the log file is transferred to the system containing mvprof, executing mvprof is usually as simple as "mvprof logfile".
In the example below, I have generated a debug log that contains output from a single request and a single source file. It was collected with the following settings:
logfile=prod_profile.log
loglevel=144
In these examples I profiled the PROD page for a stock PR8 Update 2 store that had 147 configured product custom fields. This is an actual use case and the information we found from this type of profiling was used to develop the custom field performance enhancements in later PR8 updates.
Code:Process 15990 flat statistics cumulative self fastest slowest seconds seconds calls call call name (file) 0.1135 0.1135 147 0.000681 0.001264 productfield_load_code (mm5/5.00/modules/util/customfld.mvc) 0.1507 0.0371 1 0.037190 0.037190 merchant (mm5/5.00/merchant.mvc) 0.1851 0.0344 19 0.000216 0.003527 templatemanager_initialize_item_lowlevel (mm5/5.00/features/tui/tui_mgr.mvc) 0.2088 0.0236 2 0.000027 0.023612 templatemanager_render_json_variables (mm5/5.00/features/tui/tui_mgr.mvc)
Code:Process 15990 call graph total self fastest slowest seconds seconds calls call call name (file) 0.1242 0.1135 147/147 0.000681 0.001264 module_product_field_name (mm5/5.00/modules/util/customfld.mvc) 0.1242 0.1135 0.000681 0.001264 productfield_load_code (mm5/5.00/modules/util/customfld.mvc) 0.0058 0.0058 294/300 0.000018 0.000047 db_compare_upper (mm5/5.00/lib/dbapi_mysql.mvc) 0.0048 0.0048 147/147 0.000031 0.000055 productfield_read (mm5/5.00/modules/util/customfld.mvc)
The call graph section shows each function broken down with information about callers of that function and functions that it itself directly called. Indented functions above the function in question are functions that directly called that function. Indented functions below the function are functions that it called. The graph also breaks down the time spent in the various functions as well as what percentage of the calls to that function were from this source. In the example above, all 147 of the calls to productfield_load_code were made from module_product_field_name, and 294 of 300 total calls to db_compare_upper were made from productfield_load_code.
The attached .zip file contains the raw debug log as well as the complete output from mvprof.Attached FilesLast edited by burch; 03-07-13, 02:17 PM.
Leave a comment:
-
mvcov
mvcov is a code coverage tool. Its purpose is to read a trace log and overlay a source file with information that displays which source lines correspond to executable code, which of those lines were exected and how many times each line was executed. We use this tool internally when developing test cases to ensure that all logic paths within the source code are tested. For debugging, when the source code is available, it can also be used to visualize the flow of execution.
mvcov is a command line tool and has been bundled with the MivaScript compiler on both Windows and UNIX since v5.16. When run with the --help parameter, it outputs the following helpful text describing its command line options:
Code:Usage: mvcov [options] logfile Options: --help Display this information --version Display version number and exit -p <pid> Include only log lines from the specified process_id -b <directory> Search for source files relative to <directory> -f <filename> Generate coverage output only for source file <filename> (may repeat) -o <output> Write coverage to <output>
Using mvcov
1. Enable logging: mvcov requires a trace log to generate its output. On Windows, this means that you would check the "Source File/Line Number Trace" checkbox. On UNIX, you would set your log level to 1073741824.
2. Generate a log file: After configuring logging, any requests made to the site being debugged will result in those requests being logged to the debug log. The trace log is extremely verbose, so if using this on a live site you absolutely must make use of one of the filtering mechanisms (or even better, the log cookie) to avoid slowing the site down or generating an enormous log file.
3. Run mvcov: You will need the source code, log file and mvcov tool on the same system. In order to generate the overlay, mvcov needs to be able to read the source files referenced within the log. By default, it will attempt to locate the source files relative to the current directory, but you may override this behavior with the "-b" flag. It will also, by default, generate output for every source file referenced in the log, unless you specify one or more "-f filename" options to limit its output.
In the example below, I have generated a debug log that contains output from a single run of the Miva Mia "Mazes of Miva" example. It was collected with the following settings:
logfile=maze_coverage.log
logfilter=maze/maze.mv
loglevel=1073741824
Code:#######: 505:<MvFUNCTION NAME = "Maze_Solve_PathCount" PARAMETERS = "maze var, x_pos, y_pos"> 507: 506: <MvIF EXPR = "{ l.maze:cells[ l.x_pos ][ l.y_pos ] EQ -1 }"> 191: 507: <MvFUNCTIONRETURN VALUE = 5> #######: 508: </MvIF> -: 509: 316: 510: <MvASSIGN NAME = "l.path_count" VALUE = 0> -: 511: 316: 512: <MvIF EXPR = "{ l.maze:cells[ l.x_pos - 1 ][ l.y_pos ] NE -1 }"> 102: 513: <MvASSIGN NAME = "l.path_count" VALUE = "{ l.path_count + 1 }"> 102: 514: </MvIF> -: 515: 316: 516: <MvIF EXPR = "{ l.maze:cells[ l.x_pos + 1 ][ l.y_pos ] NE -1 }"> 123: 517: <MvASSIGN NAME = "l.path_count" VALUE = "{ l.path_count + 1 }"> 123: 518: </MvIF> -: 519: 316: 520: <MvIF EXPR = "{ l.maze:cells[ l.x_pos ][ l.y_pos - 1 ] NE -1 }"> 135: 521: <MvASSIGN NAME = "l.path_count" VALUE = "{ l.path_count + 1 }"> 135: 522: </MvIF> -: 523: 316: 524: <MvIF EXPR = "{ l.maze:cells[ l.x_pos ][ l.y_pos + 1 ] NE -1 }"> 132: 525: <MvASSIGN NAME = "l.path_count" VALUE = "{ l.path_count + 1 }"> 132: 526: </MvIF> -: 527: 316: 528: <MvFUNCTIONRETURN VALUE = "{ l.path_count }"> #######: 529:</MvFUNCTION> -: 530: #######: 531:<MvFUNCTION NAME = "Maze_Solve_FollowPath" PARAMETERS = "maze var, x_pos var, y_pos var"> 146: 532: <MvIF EXPR = "{ l.maze:cells[ l.x_pos ][ l.y_pos ] EQ -1 }"> #######: 533: <MvFUNCTIONRETURN> #######: 534: </MvIF> -: 535: 146: 536: <MvASSIGNARRAY NAME = "l.maze:cells" VALUE = "-1"> 146: 537: <MvDIMENSION INDEX = "{ l.x_pos }"> 146: 538: <MvDIMENSION INDEX = "{ l.y_pos }"> 146: 539: </MvASSIGNARRAY> -: 540: 146: 541: <MvIF EXPR = "{ l.maze:cells[ l.x_pos ][ l.y_pos - 1 ] NE -1 }"> 46: 542: <MvASSIGN NAME = "l.y_pos" VALUE = "{ l.y_pos - 1 }"> 46: 543: <MvELSEIF EXPR = "{ l.maze:cells[ l.x_pos ][ l.y_pos + 1 ] NE -1 }"> 34: 544: <MvASSIGN NAME = "l.y_pos" VALUE = "{ l.y_pos + 1 }"> 34: 545: <MvELSEIF EXPR = "{ l.maze:cells[ l.x_pos + 1 ][ l.y_pos ] NE -1 }"> 42: 546: <MvASSIGN NAME = "l.x_pos" VALUE = "{ l.x_pos + 1 }"> 42: 547: <MvELSEIF EXPR = "{ l.maze:cells[ l.x_pos - 1 ][ l.y_pos ] NE -1 }"> 24: 548: <MvASSIGN NAME = "l.x_pos" VALUE = "{ l.x_pos - 1 }"> 24: 549: </MvIF> 146: 550:</MvFUNCTION>
The attached .zip file contains the complete output from mvcov as well as the raw debug log file.Attached FilesLast edited by burch; 03-07-13, 01:42 PM.
Leave a comment:
-
Advanced Diagnostics with the MivaScript debug log
This thread is intended to be a companion to my 2013 conference presentation on the same subject and to serve as a future repository for information about the MivaScript debug log mechanism and its use. I'll be updating the first few posts over the next couple days to include additional technical information and examples.
Basic Information
Debug logging is supported on MivaScript engine versions 5.10 and newer.
Configuration: Windows
On Windows, there is a simple configuration dialog that allows the debug log to be configured.
debug_logging_dialog.jpg
Mia has a single debug logging setting that is applied to all scripts. On IIS, the settings can be applied to an entire website, a directory or an individual file.
Configuration: UNIX
Logging functionality on UNIX is identical to Windows and is configured differently depending on which configuration library you are using.
If using the environment-variable based configuration library, the following environment variables are used:
MvCONFIG_LOG_FILE specifies the name of the debug log file
MvCONFIG_LOG_LEVEL specifies the individual logging functions that should be enabled
MvCONFIG_LOG_FILTER specifies what filtering rules, if any, are applied
The 3.x configuration library uses the following configuration directives:
logfile specifies the name of the debug log file
loglevel specifies the individual logging functions that should be enabled
logfilter specifies what filtering rules, if any, are applied
The values for the directives are the same for either configuration library.
Configuration: Log File
On UNIX, the log file is always created in the mivadata directory. On Windows a full path is provided.
Configuration: Log Level
The log level is a bitfield, with each field controlling a single loggable item. In practice, this means that there is a particular numeric value assigned to each item and to enable multiple item you just add their numeric values together to obtain the final log level value. On Windows, the configuration dialog takes care of this for you and it is a simple matter of checking the checkboxes for the items you would like logged.
Below is a list of the loggable items and their assigned numeric values. (This list may also be found in mivapi.h in the UNIX VM distribution packages)
Code:MvCONFIG_LOG_FUNC_CALL 16 Calls to native (MivaScript) functions MvCONFIG_LOG_FUNC_PARAM 32 Parameters to native (MivaScript) functions MvCONFIG_LOG_FUNC_RETVAL 64 Return values from native (MivaScript) functions MvCONFIG_LOG_FUNC_RETURN 128 Return from native (MivaScript) functions MvCONFIG_LOG_EXTERNAL_FUNC_CALL 256 Calls to builtin or other external functions MvCONFIG_LOG_EXTERNAL_FUNC_PARAM 512 Parameters to builtin or other external functions MvCONFIG_LOG_EXTERNAL_FUNC_RETVAL 1024 Return values from builtin or other external functions MvCONFIG_LOG_EXTERNAL_FUNC_RETURN 2048 Return from builtin or other external functions MvCONFIG_LOG_MvDO_FILE_ENTER 4096 MvDO of an entire file has begun MvCONFIG_LOG_MvDO_FILE_EXIT 8192 MvDO of an entire file has ended MvCONFIG_LOG_MvCALL 1048576 Logs raw request and response data for the MvCALL tag (requires v5.13) MvCONFIG_LOG_APPLICATION_TIMEOUT 134217728 Logs globaltimeout terminations (requires v5.13) MvCONFIG_LOG_RUNTIME_ERROR 268435456 All runtime errors MvCONFIG_LOG_FATAL_ERROR 536870912 All fatal errors MvCONFIG_LOG_TRACE 1073741824 Logs each line of source code executed
Configuration: Log Filter
In v5.13 or higher, you may apply an additional filter to the debug log to limit the log messages to those that were generated by particular source code. When a filter is specified, only those lines of code which match the filter will be logged.
The log filter directive takes the following form:
sourcefile[:[start_line][-[end_line]],...
"sourcefile" corresponds to the name of the MivaScript source file. This is generally the exact value that was passed to the MivaScript compiler when the source code was compiled.
"start_line" and "end_line" refer to source code line numbers within the source file. A range may be specified like this: "1-10". Within a range, either the start or end may be omitted. For example, "-100" means lines 1-100 and "100-" means lines 100 through the end of the file.
Source filenames and line numbers will generally be determined by examining the source code being debugged. However, they may also be inferred by generating a debug log without a filter and gathering sourcefile and line number values from the log.
Multiple filters may be specified by separating them with a comma.
v5.17 extends the filtering mechanism to add the concept of an exclusionary filter. By preceeding the filter value with "!", its function is reversed and any lines of code that do NOT match the filter are logged. Inclusionary and exclusionary filters may be combined, and will be applied in left to right order.
Log Cookie
The 5.18 engine will introduce a new type of filtering. Instead of (or in addition to) limiting the logging based on the source code, the log cookie setting allows you to restrict the logging to requests generated by clients containing a particular cookie value. There are two major components to the log cookie mechanism:
1. The log cookie configuration setting. On Windows, the cookie value is configured within the same debug log settings dialog as the rest of the settings. On UNIX, it is set using the logcookie configuration directive (3.x configuration) or MvCONFIG_LOG_COOKIE environment variable (environment based configuration).
2. The diagnostic tool which allows you to set the cookie on a target client.
I will provide additional information and screenshots on this section after the 5.18 engine release
Log File Format
The log file is a tab delimited text file containing the following fields:
Date/Time Stamp
Process ID
Type of Log Message
Compiled MivaScript file path
Source file
Source line number
Message-specific data (function return values, parameter values, MvCALL data, etc...)Last edited by burch; 03-07-13, 01:49 PM.Tags: None
Leave a comment: