my4.stap

global milestones
global phases

global msg_id

probe process(@1).function("meetmaker__show_next") {
	milestones["received_request_in_shard", $request->user_id] = gettimeofday_us()
}

probe process(@1).function("meetmaker__show_next__finalizer") {
	milestones["received_response_from_bmpid", $search_ctx->user_id] = gettimeofday_us()
}

probe process(@1).function("user_prepare_search_ctx") {
	milestones["started_preparing_search_ctx", $u->user_id] = gettimeofday_us()
}

probe process(@1).statement("user_prepare_search_ctx@src/user.c:1104") {
	milestones["finished_preparing_search_ctx", $u->user_id] = gettimeofday_us()
}

probe process(@1).function("meetmaker__show_next__respond") {
	milestones["sending_response_to_user", $u->user_id] = gettimeofday_us()

	if (["sending_request_to_bmpid", $u->user_id] in milestones) {

		p1 = milestones["received_request_in_shard", $u->user_id]     - milestones["received_request_in_event", $u->user_id]
		p2 = milestones["started_preparing_search_ctx", $u->user_id]  - milestones["received_request_in_shard", $u->user_id]
		p3 = milestones["finished_preparing_search_ctx", $u->user_id] - milestones["started_preparing_search_ctx", $u->user_id]
		p4 = milestones["sending_request_to_bmpid", $u->user_id]      - milestones["finished_preparing_search_ctx", $u->user_id]
		p5 = milestones["received_response_from_bmpid", $u->user_id]  - milestones["sending_request_to_bmpid", $u->user_id]
		p6 = milestones["sending_response_to_user", $u->user_id]      - milestones["received_response_from_bmpid", $u->user_id]
		t  = milestones["sending_response_to_user", $u->user_id]      - milestones["received_request_in_event", $u->user_id]          

		phases["1"] <<< p1
		phases["2"] <<< p2
		phases["3"] <<< p3
		phases["4"] <<< p4
		phases["5"] <<< p5
		phases["6"] <<< p6
		phases["total"] <<< t

		printf("=== user_id %d ===\n", $u->user_id)
		printf("received_request_in_event -> received_request_in_shard took %d us\n", p1)
		printf("received_request_in_shard -> started_preparing_search_ctx took %d us\n", p2)
		printf("started_preparing_search_ctx -> finished_preparing_search_ctx took %d us\n", p3)
		printf("finished_preparing_search_ctx -> sending_request_to_bmpid took %d us\n", p4)
		printf("sending_request_to_bmpid -> received_response_from_bmpid took %d us\n", p5)
		printf("received_response_from_bmpid -> sending_response_to_user took %d us\n", p6)
		printf("total request took %d us\n", t)
		printf("\n\n")
	} 

	delete milestones["received_request_in_event", $u->user_id]
	delete milestones["received_request_in_shard", $u->user_id]
	delete milestones["started_preparing_search_ctx", $u->user_id]
	delete milestones["finished_preparing_search_ctx", $u->user_id]
	delete milestones["sending_request_to_bmpid", $u->user_id]
	delete milestones["received_response_from_bmpid", $u->user_id]
	delete milestones["sending_response_to_user", $u->user_id]
}

probe process(@1).function("bmpid_index_search") {
	milestones["sending_request_to_bmpid", $search_ctx->user_id] = gettimeofday_us()
}

probe process(@1).statement("sharding_request_get_single_shard_id@src/sharding.c:525") {
	msg_id = $msg_id
}

probe process(@1).statement("sharding___meetmaker_request_get_single_shard_id@src/sharding.c:509") {
	if (msg_id == 14) { // show_next msg_id
		milestones["received_request_in_event", $user_id] = gettimeofday_us()
	}
}

probe end {
	foreach ([phase] in phases+) {
		printf("Phase %s\n", phase)
		printf("Duration min:%dus avg:%dus max:%dus count:%d\n",
		       @min(phases[phase]), @avg(phases[phase]), @max(phases[phase]),
		       @count(phases[phase]))
		printf("Duration (us):\n")
		print(@hist_log(phases[phase]));
		printf("\n")
	}
}