Bpftrace scripts capturing ICP AES-GCM performance.

icp-duration-by-size.bt

// Display time taken by various crypto funcs in nsec., grouped by
// payload length.

struct common_ctx {
	void *cc_keysched;
	size_t cc_keysched_len;
	uint64_t cc_iv[2];
	uint64_t cc_remainder[2];
	size_t cc_remainder_len;
	uint8_t *cc_lastp;
	uint8_t *cc_copy_to;
	uint32_t cc_flags;
};

struct gcm_ctx {
	struct common_ctx gcm_common;
	size_t gcm_tag_len;
	size_t gcm_processed_data_len;
	size_t gcm_pt_buf_len;
	uint32_t gcm_tmp[4];
	uint64_t gcm_ghash[2];
	uint64_t gcm_H[2];
	uint64_t gcm_Htable[12][2];
	uint64_t gcm_J0[2];
	uint64_t gcm_len_a_len_c[2];
	uint8_t *gcm_pt_buf;
	int gcm_kmflag;
	int use_avx;
}

kprobe:gcm_decrypt_final
{
	@start_dec[tid] = nsecs;
	@len_dec[tid] = ((struct gcm_ctx *)arg0)->gcm_pt_buf_len - 16;
}

kretprobe:gcm_decrypt_final
{
	$len = @len_dec[tid];
	$dur = nsecs - @start_dec[tid];

	delete(@len_dec[tid]);
	delete(@start_dec[tid]);

	@decrypt_time[$len] = hist($dur);
	@decrypt_time_avg[$len] = avg($dur);
	@decrypt_time_cnt[$len] = count();
}


kprobe:gcm_mode_encrypt_contiguous_blocks
{
	@start_enc[tid] = nsecs;
	@len_enc[tid] = arg2;
}

kretprobe:gcm_mode_encrypt_contiguous_blocks
{
	$len = @len_enc[tid];
	$dur = nsecs - @start_enc[tid];

	delete(@len_enc[tid]);
	delete(@start_enc[tid]);

	@encrypt_time[$len] = hist($dur);
	@encrypt_time_avg[$len] = avg($dur);
	@encrypt_time_cnt[$len] = count();

}

kprobe:gcm_init_ctx
{
	@start_init[tid] = nsecs;
}

kretprobe:gcm_init_ctx
{
	@gcm_init_time = hist(nsecs - @start_init[tid]);
	delete(@start_init[tid]);
}

kprobe:gcm_encrypt_final
{
	@start_enc_fin[tid] = nsecs;
}

kretprobe:gcm_encrypt_final
{
	@encrypt_final_time = hist(nsecs - @start_enc_fin[tid]);
	delete(@start_enc_fin[tid]);
}


END
{
	printf("\n\nTime spend de/encrypting, grouped by size.\n");
	printf("(1k == 1us, 1M == 1ms).\n\n");
	printf("\n\nns spend in gcm_decrypt_final().\n");
	print(@decrypt_time);
	printf("-------------\n\n");
	printf("\n\nns spend in gcm_mode_enc._cont._blocks().\n");
	print(@encrypt_time);
	printf("\n\nns spend in gcm_init_ctx().\n");
	print(@gcm_init_time);
	printf("\n\nns spend in gcm_encrypt_final().\n");
	print(@encrypt_final_time);
	printf("-------------\n\n");
	print(@encrypt_time_avg);
	print(@encrypt_time_cnt);
	print(@decrypt_time_avg);
	print(@decrypt_time_cnt);

	clear(@len_dec);
	clear(@len_enc);
	clear(@start_dec);
	clear(@start_enc);
	clear(@decrypt_time);
	clear(@decrypt_time_avg);
	clear(@decrypt_time_cnt);
	clear(@encrypt_time);
	clear(@encrypt_time_avg);
	clear(@encrypt_time_cnt);
	clear(@encrypt_final_time);
	clear(@gcm_init_time);
}

icp-total-crypto-times.bt

// Display time taken processing a gcm_ctx in nsec., grouped by
// payload length.

struct common_ctx {
	void *cc_keysched;
	size_t cc_keysched_len;
	uint64_t cc_iv[2];
	uint64_t cc_remainder[2];
	size_t cc_remainder_len;
	uint8_t *cc_lastp;
	uint8_t *cc_copy_to;
	uint32_t cc_flags;
};

struct gcm_ctx {
	struct common_ctx gcm_common;
	size_t gcm_tag_len;
	size_t gcm_processed_data_len;
	size_t gcm_pt_buf_len;
	uint32_t gcm_tmp[4];
	uint64_t gcm_ghash[2];
	uint64_t gcm_H[2];
	uint64_t gcm_Htable[12][2];
	uint64_t gcm_J0[2];
	uint64_t gcm_len_a_len_c[2];
	uint8_t *gcm_pt_buf;
	int gcm_kmflag;
	int use_avx;
}

kprobe:gcm_init_ctx
{
	@start_ctx[arg0] = nsecs;
}

kprobe:gcm_decrypt_final
{
	@dec_len[tid] = ((struct gcm_ctx *)arg0)->gcm_processed_data_len - 16;
	@dec_ctx[tid] = arg0;
}

kretprobe:gcm_decrypt_final
{
	$ctx = @dec_ctx[tid];
	$dur = nsecs - @start_ctx[$ctx];
	$len = @dec_len[tid];

	delete(@dec_ctx[tid]);
	delete(@start_ctx[$ctx]);
	delete(@dec_len[tid]);

	@dec_dur[$len] = hist($dur);
	@dec_dur_avg[$len] = avg($dur);
}

kprobe:gcm_encrypt_final
{
	@enc_len[tid] = ((struct gcm_ctx *)arg0)->gcm_processed_data_len;
	@enc_ctx[tid] = arg0;
}

kretprobe:gcm_encrypt_final
{
	$ctx = @enc_ctx[tid];
	$dur = nsecs - @start_ctx[$ctx];
	$len = @enc_len[tid];

	delete(@enc_ctx[tid]);
	delete(@start_ctx[$ctx]);
	delete(@enc_len[tid]);

	@enc_dur[$len] = hist($dur);
	@enc_dur_avg[$len] = avg($dur);
}

END
{
	printf("\n\nTime spend de/encrypting, grouped by size.\n");
	printf("(1k == 1us, 1M == 1ms).\n\n");

	print(@dec_dur);
	printf("-------------\n\n");
	print(@enc_dur);

	print(@dec_dur_avg);
	printf("-------------\n\n");
	print(@enc_dur_avg);

	clear(@start_ctx);
	clear(@dec_ctx);
	clear(@enc_ctx);
	clear(@dec_len);
	clear(@enc_len);
	clear(@dec_dur);
	clear(@enc_dur);
	clear(@dec_dur_avg);
	clear(@enc_dur_avg);

}