Skip to content

Commit 8e45dd6

Browse files
victormlgvictormlg
committed
Added stacktrace and flamegraph
Signed-off-by: Victor Moene <[email protected]>
1 parent 005358a commit 8e45dd6

File tree

3 files changed

+200
-28
lines changed

3 files changed

+200
-28
lines changed

‎contrib/cf-profile/cf-profile.py‎

Lines changed: 117 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -2,51 +2,152 @@
22
import sys
33
import json
44
import re
5+
from collections import defaultdict
6+
7+
"""
8+
This script parses profiling output from cf-agent and lists policy bundles, promises, and functions sorted by execution time.
9+
10+
Usage:
11+
$ sudo /var/cfengine/cf-agent -Kp
12+
$ python3 cf-profile.py profiling_output.json --bundles --promises --functions
13+
"""
14+
515

616
def parse_args():
717
parser = ArgumentParser()
818

19+
# parser.add_argument("profiling_output")
920
parser.add_argument("--top", type=int, default=10)
1021
parser.add_argument("--bundles", action="store_true")
1122
parser.add_argument("--promises", action="store_true")
1223
parser.add_argument("--functions", action="store_true")
24+
parser.add_argument("--flamegraph", action="store_true")
1325

1426
return parser.parse_args()
1527

16-
def profile(data, args):
1728

18-
events = sorted([event for event in data["events"]], key=lambda x: x["elapsed"], reverse=True)
29+
def format_elapsed_time(elapsed_ns):
30+
elapsed_ms = float(elapsed_ns) / 1e6
31+
32+
if elapsed_ms < 1000:
33+
return "%.2f ms" % elapsed_ms
34+
elif elapsed_ms < 60000:
35+
elapsed_s = elapsed_ms / 1000.0
36+
return "%.2fs" % elapsed_s
37+
else:
38+
elapsed_s = elapsed_ms / 1000.0
39+
minutes = int(elapsed_s // 60)
40+
seconds = int(elapsed_s % 60)
41+
return "%dm%ds" % (minutes, seconds)
42+
43+
44+
def format_label(event_type, name):
45+
if event_type == "function":
46+
return "%s() %s call" % (name, event_type)
47+
elif name == "methods":
48+
return "bundle invocation"
49+
else:
50+
return "%s %s" % (name, event_type)
51+
52+
53+
def format_columns(events, top):
54+
55+
labels = []
56+
57+
for event in events[:top]:
58+
label = format_label(event["type"], event["name"])
59+
location = "%s:%s" % (event["filename"], event["offset"]["line"])
60+
time = format_elapsed_time(event["elapsed"])
61+
62+
labels.append((label, location, time))
63+
64+
return labels
65+
1966

20-
filter = []
67+
def get_max_column_lengths(lines, indent=4):
68+
69+
max_type, max_location, max_time = 0, 0, 0
70+
71+
for label, location, time_ms in lines:
72+
max_type = max(max_type, len(label))
73+
max_location = max(max_location, len(location))
74+
max_time = max(max_time, len(time_ms))
75+
76+
return max_type + indent, max_location + indent, max_time + indent
77+
78+
79+
def profile(data, args):
80+
81+
events = data["events"]
82+
filter = defaultdict(list)
2183

2284
if args.bundles:
23-
filter.append("bundle")
85+
filter["type"].append("bundle")
86+
filter["name"].append("methods")
2487

2588
if args.promises:
26-
filter.append("promise")
89+
filter["name"] += list(
90+
set(
91+
event["name"]
92+
for event in events
93+
if event["type"] == "promise" and event["name"] != "methods"
94+
)
95+
)
2796

2897
if args.functions:
29-
filter.append("function")
98+
filter["type"].append("function")
3099

31-
if filter:
32-
events = [event for event in events if event["type"] in filter]
100+
# filter events
101+
if filter is not None:
102+
events = [
103+
event
104+
for field in filter.keys()
105+
for event in events
106+
if event[field] in filter[field]
107+
]
33108

34-
print("%-60s %-90s %20s" % ("Component", "Location", "Time"))
35-
for t in events[:args.top]:
109+
# sort events
110+
events = sorted(events, key=lambda x: x["elapsed"], reverse=True)
36111

37-
label = "%s %s" % (t["type"], t["name"])
38-
location = "%s:%s" % (t["filename"], t["offset"]["line"])
39-
time_ms = "%.2f ms" % (float(t["elapsed"]) / 1e6)
112+
lines = format_columns(events, args.top)
113+
line_format = "%-{}s %-{}s %{}s".format(*get_max_column_lengths(lines))
40114

41-
print("%-60s %-90s %20s" % (label, location, time_ms))
115+
# print top k filtered events
116+
print(line_format % ("Type", "Location", "Time"))
117+
for label, location, time_ms in lines:
118+
print(line_format % (label, location, time_ms))
119+
120+
def generate_callstacks(data):
121+
events = data["events"]
122+
123+
# hashmap = {"policy" : 0}
124+
# for event in events:
125+
# hashmap[event["id"]] = event["elapsed"]
126+
# print(json.dumps(hashmap, indent=4))
127+
128+
# for event in sorted(events, key=lambda x: x["id"].count(";"), reverse=True):
129+
# parent = ";".join(event["id"].split(";")[:-1])
130+
# hashmap[parent] -= event["elapsed"]
131+
132+
133+
with open("stack.txt", "w") as f:
134+
for event in events:
135+
f.write("%s %d\n" % (event["callstack"], event["elapsed"]))
42136

43137
def main():
44138
args = parse_args()
45139
m = re.search(r"\{[.\s\S]*\}", sys.stdin.read())
140+
# with open(args.profiling_output, "r") as f:
141+
# data = json.load(f)
46142
data = json.loads(m.group(0))
47143

48-
profile(data, args)
144+
145+
if args.flamegraph:
146+
generate_callstacks(data)
147+
else:
148+
profile(data, args)
149+
49150

50151

51152
if __name__ == "__main__":
52-
main()
153+
main()

‎libpromises/eval_context.c‎

Lines changed: 82 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -127,8 +127,13 @@ static bool EvalContextClassPut(EvalContext *ctx, const char *ns, const char *na
127127
static const char *EvalContextCurrentNamespace(const EvalContext *ctx);
128128
static ClassRef IDRefQualify(const EvalContext *ctx, const char *id);
129129

130-
static EventFrame *EventFrameCreate(char *type, const char *name, const char *source, SourceOffset offset);
130+
static EventFrame *EventFrameCreate(char *type, const char *name, const char *source, SourceOffset offset, char *id);
131131
static void EventFrameDestroy(EventFrame *event);
132+
133+
static char *BundleGetCallStackID(const Bundle *bp);
134+
static char *PromiseGetCallStackID(const Promise *pp);
135+
static char *FunctionGetCallStackID(const FnCall *fp);
136+
132137
static EventFrame *BundleToEventFrame(const Bundle *bp);
133138
static EventFrame *PromiseToEventFrame(const Promise *pp);
134139
static EventFrame *FunctionToEventFrame(const FnCall *fp);
@@ -346,6 +351,20 @@ static StackFrame *LastStackFrameByType(const EvalContext *ctx, StackFrameType t
346351
return NULL;
347352
}
348353

354+
static StackFrame *LastStackFrameByEvent(const EvalContext *ctx)
355+
{
356+
for (size_t i = 0; i < SeqLength(ctx->stack); i++)
357+
{
358+
StackFrame *frame = LastStackFrame(ctx, i);
359+
if (frame->event != NULL)
360+
{
361+
return frame;
362+
}
363+
}
364+
365+
return NULL;
366+
}
367+
349368
static LogLevel AdjustLogLevel(LogLevel base, LogLevel adjust)
350369
{
351370
if (adjust == -1)
@@ -1436,7 +1455,22 @@ void EvalContextStackPushBundleFrame(EvalContext *ctx, const Bundle *owner, cons
14361455
assert(ctx != NULL);
14371456
assert(!LastStackFrame(ctx, 0) || LastStackFrame(ctx, 0)->type == STACK_FRAME_TYPE_PROMISE_ITERATION);
14381457

1439-
EvalContextStackPushFrame(ctx, StackFrameNewBundle(owner, inherits_previous, ctx->profiling));
1458+
StackFrame *prev_frame = LastStackFrameByEvent(ctx);
1459+
StackFrame *frame = StackFrameNewBundle(owner, inherits_previous, ctx->profiling);
1460+
1461+
EventFrame *pushed_event = frame->event;
1462+
EvalContextStackPushFrame(ctx, frame);
1463+
if (pushed_event != NULL)
1464+
{
1465+
if (prev_frame == NULL || prev_frame->event == NULL)
1466+
{
1467+
pushed_event->stacktrace = SafeStringDuplicate(pushed_event->id);
1468+
}
1469+
else
1470+
{
1471+
pushed_event->stacktrace = StringFormat("%s;%s", prev_frame->event->stacktrace, pushed_event->id);
1472+
}
1473+
}
14401474

14411475
if (RlistLen(args) > 0)
14421476
{
@@ -1516,9 +1550,22 @@ void EvalContextStackPushPromiseFrame(EvalContext *ctx, const Promise *owner)
15161550

15171551
EvalContextVariableClearMatch(ctx);
15181552

1553+
StackFrame *prev_frame = LastStackFrameByEvent(ctx);
15191554
StackFrame *frame = StackFrameNewPromise(owner, ctx->profiling);
15201555

15211556
EvalContextStackPushFrame(ctx, frame);
1557+
EventFrame *pushed_event = frame->event;
1558+
if (pushed_event != NULL)
1559+
{
1560+
if (prev_frame == NULL || prev_frame->event == NULL)
1561+
{
1562+
pushed_event->stacktrace = SafeStringDuplicate(pushed_event->id);
1563+
}
1564+
else
1565+
{
1566+
pushed_event->stacktrace = StringFormat("%s;%s", prev_frame->event->stacktrace, pushed_event->id);
1567+
}
1568+
}
15221569

15231570
// create an empty table
15241571
frame->data.promise.vars = VariableTableNew();
@@ -3891,7 +3938,7 @@ void EvalContextSetProfiling(EvalContext *ctx, bool profiling)
38913938
ctx->profiling = profiling;
38923939
}
38933940

3894-
static EventFrame *EventFrameCreate(char *type, const char *name, const char *source, SourceOffset offset)
3941+
static EventFrame *EventFrameCreate(char *type, const char *name, const char *source, SourceOffset offset, char *id)
38953942
{
38963943
EventFrame *event = (EventFrame *) xmalloc(sizeof(EventFrame));
38973944

@@ -3900,7 +3947,8 @@ static EventFrame *EventFrameCreate(char *type, const char *name, const char *so
39003947
event->filename = GetAbsolutePath(source);
39013948
event->elapsed = 0;
39023949
event->offset = offset;
3903-
event->id = StringFormat("%s_%s_%s_%ld_%ld", type, name, source, offset.start, offset.line);
3950+
event->id = id;
3951+
event->stacktrace = "";
39043952

39053953
return event;
39063954
}
@@ -3926,6 +3974,7 @@ static JsonElement *EventToJson(EventFrame *event)
39263974
JsonObjectAppendString(json_event, "filename", event->filename);
39273975
JsonObjectAppendString(json_event, "id", event->id);
39283976
JsonObjectAppendInteger64(json_event, "elapsed", event->elapsed);
3977+
JsonObjectAppendString(json_event, "callstack", event->stacktrace);
39293978

39303979
JsonElement *offset = JsonObjectCreate(4);
39313980
JsonObjectAppendInteger(offset, "start", event->offset.start);
@@ -3941,19 +3990,19 @@ static JsonElement *EventToJson(EventFrame *event)
39413990
static EventFrame *BundleToEventFrame(const Bundle *bp)
39423991
{
39433992
assert(bp != NULL);
3944-
return EventFrameCreate("bundle", bp->name, bp->source_path, bp->offset);
3993+
return EventFrameCreate("bundle", bp->name, bp->source_path, bp->offset, BundleGetCallStackID(bp));
39453994
}
39463995

39473996
static EventFrame *PromiseToEventFrame(const Promise *pp)
39483997
{
39493998
assert(pp != NULL);
3950-
return EventFrameCreate("promise", PromiseGetPromiseType(pp), PromiseGetBundle(pp)->source_path, pp->offset);
3999+
return EventFrameCreate("promise", PromiseGetPromiseType(pp), PromiseGetBundle(pp)->source_path, pp->offset, PromiseGetCallStackID(pp));
39514000
}
39524001

39534002
static EventFrame *FunctionToEventFrame(const FnCall *fp)
39544003
{
39554004
assert(fp != NULL);
3956-
return EventFrameCreate("function", fp->name, PromiseGetBundle(fp->caller)->source_path, fp->caller->offset);
4005+
return EventFrameCreate("function", fp->name, PromiseGetBundle(fp->caller)->source_path, fp->caller->offset, FunctionGetCallStackID(fp));
39574006
}
39584007

39594008
void EvalContextAddFunctionEvent(EvalContext *ctx, const FnCall *fp, int64_t start)
@@ -4022,19 +4071,24 @@ void EvalContextProfilingEnd(EvalContext *ctx, const Policy *policy)
40224071

40234072
ctx->profiler.elapsed = end - start;
40244073

4025-
HashMap *map = SumEventFrames(ctx->profiler.events);
4074+
// HashMap *map = SumEventFrames(ctx->profiler.events);
40264075
JsonElement *profiling = JsonObjectCreate(2);
40274076

40284077
JsonElement *json_policy = PolicyToJson(policy);
40294078
JsonObjectAppendObject(profiling, "policy", json_policy);
40304079

40314080
JsonElement *events = JsonArrayCreate(10);
40324081
{
4033-
HashMapIterator iter = HashMapIteratorInit(map);
4034-
MapKeyValue *mkv;
4035-
while ((mkv = HashMapIteratorNext(&iter)) != NULL)
4082+
// HashMapIterator iter = HashMapIteratorInit(map);
4083+
// MapKeyValue *mkv;
4084+
// while ((mkv = HashMapIteratorNext(&iter)) != NULL)
4085+
// {
4086+
// EventFrame *event = mkv->value;
4087+
// JsonArrayAppendObject(events, EventToJson(event));
4088+
// }
4089+
for (size_t i = 0; i < SeqLength(ctx->profiler.events); i++)
40364090
{
4037-
EventFrame *event = mkv->value;
4091+
EventFrame *event = SeqAt(ctx->profiler.events, i);
40384092
JsonArrayAppendObject(events, EventToJson(event));
40394093
}
40404094
}
@@ -4047,3 +4101,19 @@ void EvalContextProfilingEnd(EvalContext *ctx, const Policy *policy)
40474101

40484102
JsonDestroy(profiling);
40494103
}
4104+
4105+
4106+
static char *BundleGetCallStackID(const Bundle *bp)
4107+
{
4108+
return StringFormat("bundle_%s_%s:%s_%s:%ld_%ld-%ld", bp->type, bp->ns, bp->name, bp->source_path, bp->offset.line, bp->offset.start, bp->offset.end);
4109+
}
4110+
4111+
static char *PromiseGetCallStackID(const Promise *pp)
4112+
{
4113+
return StringFormat("promise_%s_%ld_%ld-%ld", PromiseGetPromiseType(pp), pp->offset.line, pp->offset.start, pp->offset.end);
4114+
}
4115+
4116+
static char *FunctionGetCallStackID(const FnCall *fp)
4117+
{
4118+
return StringFormat("function_%s_%ld_%ld-%ld", fp->name, fp->caller->offset.line, fp->caller->offset.start, fp->caller->offset.end);
4119+
}

‎libpromises/eval_context.h‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -47,6 +47,7 @@ typedef struct {
4747
char *filename;
4848
SourceOffset offset;
4949
int64_t elapsed;
50+
char *stacktrace;
5051
} EventFrame;
5152

5253
typedef enum

0 commit comments

Comments
 (0)