Perforce Public Knowledge Base - Simple P4D Log Analysis
× PRODUCTS SOLUTIONS CUSTOMERS LEARN SUPPORT
Downloads Company Partners Careers Contact Free Trials
Menu Search
Perforce
Reset Search
 

 

Article

Simple P4D Log Analysis

« Go Back

Information

 
Problem
Solution
The grep utility, available on all Unix/Linux variants, provides an easy method for simple Perforce Server log analysis.
 
When analyzing a Perforce log to examine performance factors, two important things to look for are:
  • db file lock held times
  • lapse times
You will probably want to first remove client and workspace locks from the log
 
$ cat log | sed -e '/^\-\-\- meta\/db/,+1d' -e '/^\-\-\- clients\//,+1d' > log.noclientlocks

$ vtrack.py log.noclientlocks
 

See Client Workspace and Global Metadata Locks.
 

DB file locks

In general, if users are encountering a performance problem, a long database table lock is the cause. Normally, the Perforce Server obtains and releases database table (db.* file) locks very quickly. However, a large table scan, for example, might hold a relatively long read lock on a server db file. That long read lock can then block subsequent Perforce Server write operations.
 
Long read locks can block write operations (like submit) -- and long write locks can block read operations (like fstat or changes). Here below, we refer to commands holding long database locks as "culprits."
 
To detect long read locks, use the following command (noting the trailing "/" in the regex):

grep -n -C10 -E "+[0-9]{6,}ms/" p4d.log > culprits.read

To detect long write locks, use the following command (noting the trailing "$" in the regex):

grep -n -C10 -E "+[0-9]{6,}ms$" p4d.log > culprits.write

The above grep invocations will identify any command that holds locks (not just waits on them) for 100,000ms (100 seconds) or more. If that does not identify enough problem commands, you can change the six (6) to a five (5) in the regex.

The -C flag ensures context for the matches. You can adjust this value up or down to grab more or less of the surrounding text. Context is needed to capture the actual Perforce command used, as the command appears above the locking information in the log file.

Note that egrep is equivalent to 'grep -E' and could be used in the above invocation instead.

A few notes on analyzing the output:

  • Beware of wedges
    Wedges refer to commands that hold one or more locks for long periods of time because they are waiting for one or more locks on other tables. Wedges will appear in the culprits list, but they aren't really culprits and you don't generally need to optimize their execution. For example, a submit operation might take long write locks, but that submit might be being held up (wedged) by another command taking a long read lock. Look for long read 'held' locks in the track output for long submit operations.
     
  • Beware of extra context output
    The -C flag will include surrounding text in the culprits output. Make sure that the text you are looking at is actually relevant to the regex match.
     
  • Next steps
    Once you find a true culprit, try to find out why the command is slow and consider solutions accordingly. Solutions might include things like: adjust the scope of the command, implement maxscanrows, upgrade Perforce, or upgrade hardware.
If more thorough analysis is needed, try running the log file through TRACK2SQL log analysis tool. The Track2SQL tool converts the file to an SQL database against which more detailed queries can be run.
 
A variant of Track2SQL, log_analyzer.php, can quickly generate a report of several popular diagnostic queries. The log_analyzer.php script requires sqlite3, a free, light weight, public domain sql database engine.
 

Lapse times

Lapse times are a symptom of a performance problem. Lapse times do not, however, point to the cause of the problem.
 
The lapse time shows how long a given command took to complete. For some commands, like p4 sync, a long lapse time might simply be the result of transferring a large set of files over the network. However, for commands that don't transfer any files, or only transfer a small volume of files, lapse times should generally be just a few seconds, or sub-second (and not appear in the log at all). Commands showing long lapse times, but no significant database wait or held times, or no file transfer involved, generally indicate network problems.
 

To identify which commands suffer from long lapse times, you can run the following:

grep -n -B1 -E "lapse [0-9]{3,}s" p4d.log > culprits.lapse

Commands with long argument

While there are valid reasons to run a command with a large number of arguments, most of the time it can be signs of poorly optimized client operations. This grep command gives you a list of commands with long arguments:
 

egrep '\([0-9][0-9]+\)' log

Related Links

Feedback

 

Was this article helpful?


   

Feedback

Please tell us how we can make this article more useful.

Characters Remaining: 255