Contents

  1. Background
  2. Evaluator's -trace Output
  3. Evaluator's -cdebug All Output

Background

Each entry in the Vesta cache is uniquely identified by its CacheIndex. To find where an entry is stored on disk you also need its PrimaryKey. You can get the evaluator to tell you these.

If you only know the CacheIndex you can find the PrimaryKey using the GraphLog. See CacheUnderTheHood/PrimaryKeyFromCacheIndex.

An important related topic is HowCachingWorks.

Evaluator's -trace Output

The evaluator's -trace command-line flag will print a representation of the call graph after the evaluation completes. This includes the CacheIndex of every cache hit that the evaluator got and every new entry that the evaluator added to the cache.

A cache hit will be represented by a line in the trace like this: 

  12. /vesta/example.com.org/foo/bar/34/build.ves: function(): hit (ci=5678)

Where:

A cache miss will be represented by a line in the trace like this: 

  12. /vesta/example.com.org/foo/bar/34/build.ves: function():  miss

Followed later by a lit where a cache entry is added: 

  12. /vesta/example.com.org/foo/bar/34/build.ves: function(): add (ci=5678)

Evaluator's -cdebug All Output

If you add "-cdebug All" to the evaluator's command line, it will print verbose information about its interaction with the cache server (every remote procedure call to the cache server, and every response from the cache server). This is a little more helpful when investigating the contents of the cache, but can be a lot of output.

A cache hit will come from a lookup call that succeeds. A Lookup call looks like this: 

08:16:29.350 08/07/2007 -- CALLING -- Lookup (call #15)
  pk = 835d2ea50651acdc bb75117e4596bc71
  epoch = 0
  fps =
    ...

Here 835d2ea50651acdc bb75117e4596bc71 is the PrimaryKey.

The result of a lookup that's a cache hit looks like this: 

08:16:29.350 08/07/2007 -- RETURNED -- Lookup (call #15)
  result = Hit
  index = 276988
  value =
    ...

Here 276988 is the CacheIndex.

A cache miss may be a lookup call that fails: 

08:16:29.350 08/07/2007 -- RETURNED -- Lookup (call #15)
  result = Miss

However, each cache lookup call is preceded by a FreeVariables call. The evaluator proceeds to the lookup call only if the result of the FreeVariables call is non-empty, as in this case: 

08:16:29.353 08/07/2007 -- CALLING -- FreeVariables (call #16)
  pk = 478ca864f5565fb9 e2cad9b4c396b415

08:16:29.353 08/07/2007 -- RETURNED -- FreeVariables (call #16)
  epoch = 1
  isEmpty = false
  names =
    ...

If the result of the FreeVariables call is empty (meaning that there there are no cache entries for that PrimaryKey), no Lookup call is made. A FreeVariables call with an empty result says "isEmpty = true": 

17:50:35.568 08/08/2007 -- CALLING -- FreeVariables (call #75)
  pk = e668b1f3fe28ed85 0c32d30be573cf1b

17:50:35.569 08/08/2007 -- RETURNED -- FreeVariables (call #75)
  epoch = 0
  isEmpty = true
  names =
  names.tbl = <empty>

After a cache miss the evaluator will add cache entry once in completes the work of the function call. Here's an example of a call to add an entry: 

09:07:14.754 08/09/2007 -- CALLING -- AddEntry (call #71)
  pk = 6e47065e33ef5c47 979276a1ed5ec41e
  names =
    nm[0] = ...
    ...
  fps =
    fp[0] = ...
    ...
  value =
    ...
  model = 2381851557
  kids = { 15603 }
  sourceFunc = /vesta/example.com.org/foo/bar/34/build.ves/func(), line 33, col 8

09:07:14.754 08/09/2007 -- RETURNED -- AddEntry (call #71)
  result = Entry Added
  ci = 23622

The CacheIndex of the new entry is 23622. Its PrimaryKey is 6e47065e33ef5c47 979276a1ed5ec41e.

It called another function with CacheIndex 15603. "sourceFunc" is a text string that gets stored in the cache to help users identify what a PrimaryKey corresponds to.

If you don't need the full debug output but you are looking for the PrimaryKey and CacheIndex of some entries, you may want to pass the "-cdebug All" output through grep: 

% vmake -cdebug All | grep -E 'CALLING|RETURNED|pk = |result = |ci = |index = |isEmpty = '
...
09:07:13.602 08/09/2007 -- CALLING -- FreeVariables (call #2)
  pk = 886d4337d383f799 74f0ebbe997b2378
09:07:13.602 08/09/2007 -- RETURNED -- FreeVariables (call #2)
  isEmpty = true
09:07:13.602 08/09/2007 -- CALLING -- FreeVariables (call #3)
  pk = ab6ec2cfbf411716 a5ef62bd5cfba296
09:07:13.602 08/09/2007 -- RETURNED -- FreeVariables (call #3)
  isEmpty = false
09:07:13.603 08/09/2007 -- CALLING -- Lookup (call #4)
  pk = ab6ec2cfbf411716 a5ef62bd5cfba296
09:07:13.603 08/09/2007 -- RETURNED -- Lookup (call #4)
  result = Hit
  index = 15508
...
09:07:14.782 08/09/2007 -- CALLING -- AddEntry (call #88)
  pk = fdc24478070e23e3 424e7098d6999a4d
09:07:14.788 08/09/2007 -- RETURNED -- AddEntry (call #88)
  result = Entry Added
  ci = 23624
...