Skip to content

.profile - Function Run Time and Memory Use Analyzer

Overview

The .profile module provides an api for investigating memory use and run time for q/kdb+.

Basic Usage

.profile.go["func 1";::]

Running the profiler

The profiler is run using the binary function .profile.go. The parameters are listed, in order, below:

Argument Type Description
expression string A string representing a q expression with the function to be profiled
userSettings dictionary A dictionary to specify the settings for the profiler run

The expression argument must be a string that represents a q expression. The expression must begin with a function that can be profiled, followed by any code necessary for constructing the arguments to the function. The first function in the expression is the only function that will be profiled. Any functions that are used to construct the arguments to this function will not be profiled. The function to be profiled cannot be called as part of a binary . or @ expression. If the expression contains multiple statements (separated by semi-colons or by newlines followed by non-whitespace characters in the first column) then only the first statement will be profiled.

There are 10 settings available to the profiler. These are:

  • context
  • functions
  • contexts
  • ignoreFunctions
  • ignoreContexts
  • spaceOrTime
  • protectedRun
  • trace
  • subtractChild
  • logAnon

These settings are detailed below. To modify settings from their default values, provide a dictionary of the modified settings as the userSettings argument. If a dictionary lacks a setting as one of its keys, the default value will be used. If only default settings are desired, use generic null ((::)) as the userSettings argument.

The profiler will search through the call graph for the given function and locate all functions that are called by said function. It will then run through the main function and record the runtime and memory usage for each function in the call graph that is accessible by the profiler. The profiler can only look at rewriteable functions; thus, any locked functions are off limits to the profiler, and will not appear in the output table from the profiler. Locked contexts must be pulled into your workspace to view the results of profiling those functions. The .profile context cannot be profiled.

There are a few circumstances where the profiler must replace function calls in a function with references to global functions. For example, if logAnon mode is set, then anonymous functions in a function must be replaced with global functions. In addition, recursive function calls using .z.s must be replaced with the original function name to allow profiling.

The necessary modifications will increase the global variable count of the function, potentially exceeding the global variable limit for q functions. If this limit is exceeded, then the function will not be re-written, an error message will be printed to the screen, and the function will not be included in the profiler results table.

Under the hood, the profiler rewrites functions to add profiling logic to log the runtime and memory usage. As such, any functions called during the profiler execution should not themselves overwrite any globally defined functions that the user wants to profile. Doing so can prevent subsequent profiling of that function. Furthermore, using value or similar functions to access a function's definition is not guaranteed to produce the same result when profiling because the rewritten function will be accessed as opposed to the original function.

Under most circumstances, the profiler will be able to run recursive function projections (i.e. a function projection that calls itself recursively). However, due to the implementation of the profiler, this necessitates the creation of a temporary copy of the function lacking the projected arguments that must be called from the function using a global variable. As stated above, this could cause the global reference limit to be exceeded, preventing profiling of the function.

Recursive calls to function projections are logged with the name of the projected function. See examples for more details.

The profiler cannot be run on multithreaded functions. Thus, all calls to peach are replaced with calls to each. If the user wants a given function to still make calls to peach, then that function must be excluded from the profiling operation by using the ignoreFunctions setting.

The profiler cannot be run on any k functions (even k functions defined by the user) because such functions are not considered to be rewriteable. Furthermore, profiling on-disk functions is prohibited.

Settings

The second argument to the profiler is a dictionary of settings. The for any settings not present in the dictionary, the default settings will be used. To use all of the default settings, provide generic null as the userSettings argument. The available profiler settings are described below:


context

Type: symbol

Default: The current execution context (found by calling system "d")

The context that the function should be executed in. The default value is the execution context where the .profile.go is called. If the function is located in a context other than its execution context, then the function name in the string argument to .profile.go must be the fully qualified name of the function.


functions

Type: symbol[]

Default: ()

A list of functions that the user also wants to analyze when profiling. Under most circumstances, the profiler should be able to locate all functions in the call graph for the given function. However, there are some situations where functions will be missed. For example, when a function is called from a string evaluated with system or value.

If a function is not automatically located by the profiler, it can be explicitly included by listing it in the functions setting list. Including a function in this setting will cause all functions in the call stack of that function to be profiled as well. The names of the supplied functions are their names in the global context.

The presence of a function in the ignoreFunctions list will take precedence over its inclusion in the functions setting list or in the list of functions called by the included function.

The presence of a function in the functions setting list will take precedence over its presence in the ignoreContexts list. In other words, functions in the functions list and all functions in their call stacks will be profiled regardless of the contents of the ignoreContexts list.


contexts

Type: symbol[]

Default: ()

A list of contexts whose functions the user also wants to profile. Similar to the functions setting, a list of contexts may be provided to find functions that the profiler would otherwise be unable to locate. The presence of a function as a result of the ignoreContexts list will take precedence over its inclusion in the contexts list.


ignoreFunctions

Type: symbol[]

Default: ()

A list of functions that the user does not want to profile. The names of the supplied functions are their names in the global context.

If a function is in both the functions list and the ignoreFunctions list, it will not be profiled. Child functions that are called by any functions in the ignoreFunctions list will still be profiled, with the exception of anonymous functions defined within the functions in the ignoreFunctions list (if logAnonmode is on).


ignoreContexts

Type: symbol[]

Default: ()

A list of contexts whose functions the user does not want to profile. If a context appears in both the contexts list and the ignoreContexts list, the context's functions will not be profiled. If a function appears in both the functions list and ignoreContexts list, the function will be profiled.


spaceOrTime

Type: symbol

Default: both

A symbol to set whether the profiler profiles memory usage (space), runtime (time), or both (both). Profiling only memory or runtime will reduce profiler overhead.


protectedRun

Type: boolean

Default: 0b (off)

Indicates whether the profiler should be run in a mode where functions that throw errors are logged in the results. This is useful when the call stack includes functions that contain internal catch statements and will still return a valid result even if a child function throws an error. This mode introduces additional runtime and space usage overhead costs for each function call.


trace

Type: boolean

Default: 0b (off)

Indicates whether the profiler should log function IDs during execution, thus allowing the profiler to create a call tree for the function execution. This mode causes the profiler to run slower because the overhead time and space for each function call increases by approximately 1 microsecond and 80 bytes. This mode is necessary to allow one to calculate the TMC and SMC, and it allows construction of a tree of the function call. This mode is automatically activated if subtractChild mode is on.


subtractChild

Type: boolean

Default: 0b (off)

Indicates whether the profiler should subtract the run time and memory usage of child functions. Switching to this mode will not affect any of the results from the table (i.e. the time and space measurements will be the same as if the user ran trace mode), though it will increase the time taken to process the results table. This mode automatically activates trace mode.


logAnon

Type: boolean

Default: 0b (turn off analysis)

Indicates whether the profiler should analyze anonymous functions that are defined within another function. Since anonymous functions do not have names in the global namespace, the profiler assigns each function a name that begins with the name of the parent function followed by the string " anon", followed by a number which indicates which anonymous function is being logged. The number starts at zero for the first anonymous function, and increases monotonically for each subsequent anonymous function.

For example, the first anonymous function in the parent function .foo.a would be .foo.a anon0. If an anonymous function itself defines anonymous functions, each of those will have the name of its parent, followed by its another anon string and an id number. For example, if .foo.a anon0 contained an anonymous function, that function would be named .foo.a anon0 anon0.

If identical functions are defined twice in the parent function, they will appear as separate entries in the results table. To view which function's names correspond to which anonymous functions, call .profile.viewAnons. This will return a dictionary of the anonymous functions stored in order of their appearance in the parent function. Functions whose name contains the signifier for an anonymous function (i.e. " anon" followed by a digit) cannot be profiled. Functions defined as strings (.e.g. calling system or value) will not be included in the profiling even if logAnon mode is on. Any anonymous functions defined in functions from the ignoreFunctions list will not be profiled even if logAnon mode is on.

Output

Different profiler settings will generate different output tables. Every profiler results table is grouped by function name. The number of calls to each function is always reported. For a other result fields, the average, min, and max values for each are shown. The total time is only reported if trace or subtractChild modes are on, as without the trace the reported values may be incorrect for functions that recursively call themselves. The types of result fields are listed below:

Field Description
Space The memory space in bytes that was used during the function execution.
SMC Stands for Space Minus Children. This is the space used by the given function minus the space used by the child function with the largest memory use. This calculation represents the maximum possible memory used exclusively by the parent function. The real memory usage could be less if the memory used by child functions does not overlap, and therefore this value should be interpreted with caution.
Time The time (reported as a timespan) for the run. The timespan datatype reports a number with a nanosecond scale, though the precision of this number can vary depending on the machine running the profiler.
TMC Stands for Time Minus Children. This is the run time for the given function execution minus the sum of the run times for all the child functions.

If trace or subtractChild mode is on, then the raw runtime and space measurements for each function will be reported in addition to the average, min and max results. Furthermore, TMC and SMC results are only reported, if subtractChild mode is on.

The output table when the spaceOrTime setting is both shows both space and time measurements. The output table when the setting is space shows only the space measurements, while the output table when the setting is time only shows time measurements.

If either trace or subtractChild mode is on, then an id (a long) is reported for each function, along with the id for the parent and child functions. These ids allow the user to construct a directed graph for the function call by running the visual inspector on the unkeyed and ungrouped table. The profiled function at the top of the stack (i.e. the first function in the string argument to .profile.go) has a parent id of 0, and an id of 1. Ids increase monotonically in the order that functions are called. If protectedRun mode is off, then it is possible that not all function ids from 0 to the maximum function id will appear in the results, since functions that throw errors will be assigned ids but will not be logged.

Profiling Overhead

By its nature, logging time and space data with the profiler requires some overhead. This overhead is included in the reported results. Each function call in the profiler will log slightly more space and a slightly longer runtime than it actually took to run the function.

Overhead costs are minimized for profiling a single metric (either space or time) without protectedRun mode and without logging IDs (which occurs if trace or subtractChild mode is on). Conversely, overhead costs are maximized by running both types of profiles with protectedRun mode and trace mode on. Turning logAnon mode on will increase the time for the profiler to execute because a greater number of functions are being measured.

Functions at different locations on the call stack tend to exhibit slightly different overhead. Functions at the end of a call branch (i.e. functions with no child functions) measure less overhead time than parent functions because they only measure the time for function execution, not any of the overhead needed to log the data. Space overhead does not follow the same pattern; child functions at the end of the call stack also exhibit overhead space.

When running the time profiler without protectedRun mode and without logging the ID of each function, the overhead time for parent functions is approximately 2 microseconds. Running the time profiler with the ID logger active adds an additional microsecond. Child functions at the end of a call branch have little overhead time (less than a microsecond) when run with the time profiler.

When running the space profiler without protectedRun mode, parent functions have space overhead of roughly 600 bytes, and child functions at the end of a call stack may have less than 600 bytes overhead. Running the time profiler with protectedRun mode adds approximately 6 microseconds of addition runtime, though this appears to depend on the function. Approximately 600-1000 bytes of additional space is typically added while in protectedRun mode, though again, this seems to depend on the function.

Multithreading Issues

The profiler cannot profile multithreaded functions. Multithreading is allowed within functions that are profiled. However, a function that is being profiled (i.e. having its runtime and memory usage logged) cannot be called in a multithreaded fashion. This is because the function will attempt to log its profiling results in a separate thread, which does not have access to the global variables where the results are recorded.

As such, the profiler replaces calls to peach with calls to each. However, there are specific circumstances where q will call peach behind the scenes, or where multithreading may still occur. Such situations may cause the profiler to throw an error.

The profiler will not locate and replace peach if it is found in a string. If such a string contains valid q and is called by system or value, then peach will be used. This may cause the profiler to throw an error.

The function .Q.fc uses multithreading if possible. .Q.fc is not replaced by the profiler, and as such may cause the profiler to throw an error if run on a named global function or if logAnon mode is on.

Select statements of the form select .. by sym,.. from t where sym in ..,.. use peach to achieve multithreading if run on tables with the g (grouped) or p (parted) attributes. This will cause the profiler to throw an error if any functions defined within the select statement are profiled. For example, the following function runs a select statement that makes calls to peach because the table has a column with the g attribute.

// @returns {Type} Enter a return description here...
.example.multithreading : {
        t:([] a: til 10000; b: `g#10000?`a`b`c);
        select a:{x+1} each a by b from t where b in `a`b
    }

There are at least three solutions to the above mentioned issues. The simplest is to set the number of slave threads to zero. Alternatively, if the function in the multithreaded call is an anonymous function then logAnon mode can be set to off. However, this would also prevent any profiling of other anonymous functions. Finally, if the function is a named global function, then the function that is run in parallel can be excluded from profiling by including it in the ignoreFunctions settings parameter.

Visualization

The function .profile.display.go will output a Graphics Window that displays an overview of the profiler results. The function takes the same arguments as .profile.go. To ensure proper display of the visual, the user settings will be overridden to turn debug mode off, subtractChild mode on, and perform both space and time profiling with the spaceOrTime setting set to both.

The graphical output of this function will display four charts. These are listed below:

Visual Description
Call Tree Weighted By Time This is a tree showing the call stack for the expression. Each node in the tree is given a weight based on the time spent executing that node.
Call Tree Weighted By Time - Children This is a tree showing the call stack for the expression. Each node in the tree is given a weight based on the time spent executing that node minus the time spent executing it's children.
Call Tree Weighted By Space This is a tree showing the call stack for the expression. Each node in the tree is given a weight based on the memory usage required to execute the node.
Timeline Coloured By Space This is a timeline of the expression execution, where each bar is coloured by the memory required for the execution.

In the Analyst workspace, it is possible to profile expressions by right-clicking on the line or highlighted expression, then clicking profile in the dropdown menu. This will open up a separate window for profiling, which will provide access to the above mentioned visuals.

Examples

Shown below is an example of how to run the profiler, along with sample output. Here, the profiler is run on the function .example.a:

.example.a : {.example.b 10;
          .example.b 20;
          .example.b 100;
          .example.b 500};
.example.b : {do[`int$x * 5.474; cos each til 1000]};

.profile.go[".example.a[]";::];

The output for this function may resemble the following table but exact runtimes will likely differ:

/=> name      | calls avgTime              minTime              maxTime              avgSpace minSpace maxSpace
/=> ----------| -----------------------------------------------------------------------------------------------
/=> .example.a| 1     0D00:00:00.621272000 0D00:00:00.621272000 0D00:00:00.621272000 42320    42320    42320
/=> .example.b| 4     0D00:00:00.155312750 0D00:00:00.009994000 0D00:00:00.493024000 41200    41200    41200

Shown below are examples of how to modify the settings of profiling run by creating dictionaries of the altered settings. The following dictionary would allow modification of the execution context when running the profiler:

newSettings : enlist[`context]! enlist ".foo"

The following dictionary would modify multiple settings:

newSettings : `spaceOrTime`protectedRun`context!(`time;1b;".foo")

All possible results columns are shown in the following example, again using the .example.a function:

.profile.go[".example.a[]";enlist[`subtractChild]!enlist 1b];

/=> name      | calls totalTime            avgTime              minTime              maxTime              avgSpace minSpace maxSpace totalTMC             avgTMC               minTMC               maxTMC               avgSMC minSMC maxSMC id      parents children                              time                                                                                space                   TMC                                                                                 SMC
/=> ----------| -----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
/=> .example.a| 1     0D00:00:00.585301000 0D00:00:00.585301000 0D00:00:00.585301000 0D00:00:00.585301000 42768    42768    42768    0D00:00:00.000032000 0D00:00:00.000032000 0D00:00:00.000032000 0D00:00:00.000032000 1568   1568   1568   ,1      ,0      ,2 3 4 5                              ,0D00:00:00.585301000                                                               ,42768                  ,0D00:00:00.000032000                                                               ,1568
/=> .example.b| 4     0D00:00:00.585269000 0D00:00:00.146317250 0D00:00:00.009474000 0D00:00:00.464586000 41200    41200    41200    0D00:00:00.585269000 0D00:00:00.146317250 0D00:00:00.009474000 0D00:00:00.464586000 41200  41200  41200  2 3 4 5 1 1 1 1 (`long$();`long$();`long$();`long$()) 0D00:00:00.009474000 0D00:00:00.018493000 0D00:00:00.092716000 0D00:00:00.464586000 41200 41200 41200 41200 0D00:00:00.009474000 0D00:00:00.018493000 0D00:00:00.092716000 0D00:00:00.464586000 41200 41200 41200 41200

If the profiler results table is unkeyed and ungrouped using the function below, it can be analyzed by the visual inspector to construct a network of the function call. Note that .profile.format.network can only be run if trace or subtractChild mode is on (since function IDs are only returned to the user in that situation):

.profile.format.network .profile.go[".example.a[]";enlist[`subtractChild]!enlist 1b];

The profiler results can also be visualized with .profile.display.go. This will create a variety of tree plots to allow visualization of the call tree of the profiler run. These trees show the runtime and space used by each function call. In addition, a timeline is reported in these results. The profiler will automatically be run with subtractChild mode, the spaceOrTime setting configured to both, and debug mode off.

.profile.display.go[".example.a[]";::];

It is possible to profile anonymous functions using the logAnon setting. Here, the profiler is run on the function .example.a, and the anonymous functions follow the naming convention described above:

.example.a : {{}[];{{}[]}[];};
.profile.go[".example.a[]";enlist[`logAnon]!enlist 1b];

/=> name                  | calls avgTime              minTime              maxTime              avgSpace minSpace maxSpace
/=> ----------------------| -----------------------------------------------------------------------------------------------
/=> .example.a            | 1     0D00:00:00.000046000 0D00:00:00.000046000 0D00:00:00.000046000 3808     3808     3808
/=> .example.a anon0      | 1     0D00:00:00.000010000 0D00:00:00.000010000 0D00:00:00.000010000 1680     1680     1680
/=> .example.a anon1      | 1     0D00:00:00.000020000 0D00:00:00.000020000 0D00:00:00.000020000 2672     2672     2672
/=> .example.a anon1 anon0| 1     0D00:00:00.000009000 0D00:00:00.000009000 0D00:00:00.000009000 1712     1712     1712

It is possible to profile function projections, even those that make recursive calls. The convention under those circumstances is to report the recursive calls (using .z.s) with the name of the projected function. Notice below that .example.a is called six times due to the recursive function invocation.

.example.a : {[x;y] $[x > 0;.z.s[x-1;y];y]}[5];
.profile.go[".example.a[]";enlist[`logAnon]!enlist 1b];

/=> name      | calls avgTime              minTime              maxTime              avgSpace minSpace maxSpace
/=> ----------| -----------------------------------------------------------------------------------------------
/=> .example.a| 6     0D00:00:00.000043500 0D00:00:00.000010000 0D00:00:00.000077000 4936     1904     7936

As discussed above, the profiler introduces some overhead runtime and memory usage to every function call. This is particularly a problem for functions with very short runtime, where the overhead makes a higher percentage of the actual function's runtime and memory usage.

To illustrate the problem, in the example below, notLong is called one million times, while actuallyLong is called once. The million runs of notLong takes approximately 0.5 seconds. However, the profiler will measure a total time of approximately 4 seconds for all million function calls.

.example.actuallyLong: {do[1000; cos each til 10000]};
.example.toFloat: {`float$x};
.example.notLong: {.example.toFloat x};
.example.foo: {
    .example.actuallyLong[];
    .example.notLong each til 1000000;
    };
t:.profile.go[".example.foo[]";enlist[`spaceOrTime]!enlist `time];
select name, totalTime : calls * avgTime from t;
/ => name                  totalTime
/ => ------------------------------------------
/ => .example.actuallyLong 0D00:00:01.734772000
/ => .example.foo          0D00:00:07.541464000
/ => .example.notLong      0D00:00:04.308000000
/ => .example.toFloat      0D00:00:01.435000000

.profile.default

Creates the default settings object for the profiler

Returns:

Name Type Description
<returns> dict The default settings for the profiler
<returns>.i_.null null
<returns>.i_.type symbol
<returns>.i_.extensions symbol[]
<returns>.context string
<returns>.functions symbol[]
<returns>.contexts symbol[]
<returns>.ignoreFunctions symbol[]
<returns>.ignoreContexts symbol[]
<returns>.spaceOrTime symbol
<returns>.protectedRun boolean
<returns>.subtractChild boolean
<returns>.logAnon boolean
<returns>.debug boolean
<returns>.trace boolean
<returns>.lines boolean

.profile.go

Runs the profiler and returns a table of results. The results table always has the name and calls columns, and may have additional columns depending on the settings.

  • time - The runtime for a function. Only present if spaceOrTime setting is time or both and the trace or subtractChild setting is true.
  • totalTime - The total runtime for all calls to a function. Only present if the spaceOrTime setting is time or both and the trace or subtractChild setting is true.
  • avgTime - The average runtime for the function. Only present if spaceOrTime setting is time or both.
  • maxTime - The max runtime for the function. Only present if spaceOrTime setting is time or both.
  • minTime - The min runtime for the function. Only present if spaceOrTime setting is time or both.
  • TMC - The runtime for a function minus the total runtime of the function's child functions. Only present if spaceOrTime setting is time or both and the subtractChild setting is true.
  • totalTMC - The total TMC for all calls to a function. Only present if spaceOrTime setting is time or both and the subtractChild setting is true.
  • avgTMC - The average TMC for a function. Only present if spaceOrTime setting is time or both and the subtractChild setting is true.
  • maxTMC - The maximum TMC for a function. Only present if spaceOrTime setting is time or both and the subtractChild setting is true.
  • minTMC - The minimum TMC for a function. Only present if spaceOrTime setting is time or both and the subtractChild setting is true.
  • space - The memory usage for a function. Only present if spaceOrTime setting is space or both and the trace or subtractChild setting is true.
  • avgSpace - The average memory usage for the function. Only present if spaceOrTime setting is space or both.
  • maxSpace - The maximum memory usage for the function. Only present if spaceOrTime setting is space or both.
  • minSpace - The minimum memory usage for the function. Only present if spaceOrTime setting is space or both.
  • SMC - The memory usage for a function minus the maximum memory usage of the function's child functions. Only present if spaceOrTime setting is space or both and the subtractChild setting is true.
  • avgSMC - The average SMC for a function. Only present if spaceOrTime setting is space or both and the subtractChild setting is true.
  • maxSMC - The maximum SMC for a function. Only present if spaceOrTime setting is space or both and the subtractChild setting is true.
  • minSMC - The minimum SMC for a function. Only present if spaceOrTime setting is space or both and the subtractChild setting is true.
  • id - A list of longs to uniquely identify every function call. The first function call has an id of 1, and the ids of subsequent function calls increase monotonically. Only present the trace or subtractChild setting is true.
  • parents - The parent function's id of each function call. The root function has a parent id of 0. Only present the trace or subtractChild setting is true.
  • children - A list of the ids of the child functions called by a given function. Only present the trace or subtractChild setting is true.

Parameter(s):

Name Type Description
expr string The expression to profile
sts dict A dictionary of the user defined settings for the profiling

Returns:

Name Type Description
<returns> table Depending on the mode, a table is returned with columns from a subset of the summarizedResult table.
<returns>.name symbol
<returns>.calls long

Example: Run the profiler

 This will run the profiler with default settings

 .profile.go["func[]";::]

 This will run the time profiler with trace mode active

 .profile.go["func[]";`spaceOrTime`trace!(`time;1b)]

.profile.viewAnons

Returns a dictionary containing all anonymous functions that were modified during the profiling. This allows the user to correlated function names in the profiler results table to the actual functions.

Returns:

Name Type Description
<returns> dict A dictionary where the keys are symbols corresponding to function names and the values are the anonymous functions themselves.
<returns>. fn Repeatable;