Measuring time using timestamp has strange results

[mrjbom]

Hello.
I am trying to measure the render time using timestamp queries.

I have this code:

if (vkBeginCommandBuffer(commandBuffers[imageIndex], &beginInfo) != VK_SUCCESS) {
	throw MakeErrorInfo("Failed to begin recording command buffer!");
}

vkCmdResetQueryPool(commandBuffers[imageIndex], queryPools[imageIndex], 0, 2);
vkCmdWriteTimestamp(commandBuffers[imageIndex], VK_PIPELINE_STAGE_TOP_OF_PIPE_BIT, queryPools[imageIndex], 0);

vkCmdBeginRenderPass(commandBuffers[imageIndex], &renderPassInfo, VK_SUBPASS_CONTENTS_INLINE);
vkCmdBindPipeline(commandBuffers[imageIndex], VK_PIPELINE_BIND_POINT_GRAPHICS, graphicsPipeline);

VkBuffer vertexBuffers[] = { vertexBuffer };
VkDeviceSize offsets[] = { 0 };
vkCmdBindVertexBuffers(commandBuffers[imageIndex], 0, 1, vertexBuffers, offsets);
vkCmdBindIndexBuffer(commandBuffers[imageIndex], indexBuffer, 0, VK_INDEX_TYPE_UINT16);
vkCmdBindDescriptorSets(commandBuffers[imageIndex], VK_PIPELINE_BIND_POINT_GRAPHICS, pipelineLayout, 0, 1, &descriptorSets[imageIndex], 0, nullptr);

for (size_t i = 0; i < iterationsNumber; ++i) {
	vkCmdDrawIndexed(commandBuffers[imageIndex], static_cast<uint32_t>(indices.size()), 1, 0, 0, 0);
}

vkCmdEndRenderPass(commandBuffers[imageIndex]);

vkCmdWriteTimestamp(commandBuffers[imageIndex], VK_PIPELINE_STAGE_BOTTOM_OF_PIPE_BIT, queryPools[imageIndex], 1);
if (vkEndCommandBuffer(commandBuffers[imageIndex]) != VK_SUCCESS) {
	throw MakeErrorInfo("Failed to record command buffer!");
}

So, if iterationsNumber is equal to 1, then I get the following results:
Total frametime: 0.354 ms
Square command buffer rendertime: 0.016 ms

But if the iterationsNumber is 2000, then I get strange results:
Total frametime: 5.483 ms
Squares command buffers rendertime: 2.331 ms

Obviously, the imgui render time could not grow by itself, which means that the frame time is considered incorrect.

The only thing I do in my scene is render 2 command buffers, an imgui command buffer and a command buffer with squares.

I’ll leave my render function just in case:

Render code(It also shows how I take data from the query pool and count the time)

void MainWindow::drawFrame()
{
	//Waiting for the fence to be ready(Waiting for the command buffer to finish executing for the frame)
	vkWaitForFences(logicalDevice, 1, &inFlightFences[currentFrame], VK_TRUE, UINT64_MAX);

	//Acquire image from swapchain
	uint32_t imageIndex;
	//UINT64_MAX disables timeout, timeout is infinite
	VkResult result = vkAcquireNextImageKHR(logicalDevice, swapchain, UINT64_MAX, imageAvailableSemaphores[currentFrame], VK_NULL_HANDLE, &imageIndex);
	if (result == VK_ERROR_OUT_OF_DATE_KHR) {
		recreateSwapchain();
		return;
	}
	else if (result != VK_SUCCESS && result != VK_SUBOPTIMAL_KHR) {
		throw MakeErrorInfo("Failed to acquire swapchain image!");
	}

	// Check if a previous frame is using this image (i.e. there is its fence to wait on)
	if (imagesInFlight[imageIndex] != VK_NULL_HANDLE) {
		vkWaitForFences(logicalDevice, 1, &imagesInFlight[imageIndex], VK_TRUE, UINT64_MAX);
	}

	static std::vector<bool> isFirstTimeFrameRender(MAX_FRAMES_IN_FLIGHT, true);
	if (isFirstTimeFrameRender[currentFrame] == false) {
		uint64_t timestampsResults[2];
		vkGetQueryPoolResults(logicalDevice, queryPools[imageIndex], 0, 2, sizeof(timestampsResults), timestampsResults, 0, VK_QUERY_RESULT_64_BIT);
		//timestampsResults[0] is start point
		////timestampsResults[1] is end point
		VkPhysicalDeviceProperties deviceProperties;
		vkGetPhysicalDeviceProperties(physicalDevice, &deviceProperties);
		float nanosecondsInTimestamp = deviceProperties.limits.timestampPeriod;
		float timestampValueInMilliseconds = ((timestampsResults[1] - timestampsResults[0]) * nanosecondsInTimestamp) / 1000000;
		g_timestampValueInMilliseconds = timestampValueInMilliseconds;
	}
	else {
		isFirstTimeFrameRender[currentFrame] = false;
	}

	// Mark the image as now being in use by this frame
	imagesInFlight[imageIndex] = inFlightFences[currentFrame];

	glfwGetWindowPos(window, &windowXPos, &windowYPos);

	updateCommandBuffer(imageIndex);
	imguiUpdateCommandBuffer(imageIndex);

	updateUniformBuffer(imageIndex);

	//Submitting the command buffer
	//Each entry in the waitStages array corresponds to the semaphore with the same index in pWaitSemaphores.
	VkSemaphore waitSemaphores[] = { imageAvailableSemaphores[currentFrame] };
	std::vector<VkPipelineStageFlags> waitStages = { VK_PIPELINE_STAGE_COLOR_ATTACHMENT_OUTPUT_BIT };
	VkSubmitInfo submitInfo{};
	submitInfo.sType = VK_STRUCTURE_TYPE_SUBMIT_INFO;
	//The first three parameters specify which semaphores to wait on before execution begins
	//and in which stage(s) of the pipeline to wait.
	//We want to wait with writing colors to the image until it's available, so we're specifying the stage of the graphics pipeline that writes to the color attachment.
	submitInfo.waitSemaphoreCount = 1;
	submitInfo.pWaitSemaphores = waitSemaphores;
	submitInfo.pWaitDstStageMask = waitStages.data();
	std::vector<VkCommandBuffer> currentCommandBuffers = { commandBuffers[imageIndex], imguiCommandBuffers[imageIndex] };
	submitInfo.commandBufferCount = 2;
	submitInfo.pCommandBuffers = currentCommandBuffers.data();
	std::vector<VkSemaphore> signalSemaphores = { renderFinishedSemaphores[currentFrame], imguiRenderFinishedSemaphores[currentFrame] };
	submitInfo.signalSemaphoreCount = 2;
	submitInfo.pSignalSemaphores = signalSemaphores.data();

	//Restore the fence to the unsignaled state
	vkResetFences(logicalDevice, 1, &inFlightFences[currentFrame]);

	//Start executing the command buffer
	if (vkQueueSubmit(graphicsQueue, 1, &submitInfo, inFlightFences[currentFrame]) != VK_SUCCESS) {
		throw MakeErrorInfo("Failed to submit draw command buffer!");
	}

	VkPresentInfoKHR presentInfo{};
	presentInfo.sType = VK_STRUCTURE_TYPE_PRESENT_INFO_KHR;
	presentInfo.waitSemaphoreCount = 2;
	presentInfo.pWaitSemaphores = signalSemaphores.data();

	VkSwapchainKHR swapchains[] = { swapchain };
	presentInfo.swapchainCount = 1;
	presentInfo.pSwapchains = swapchains;
	presentInfo.pImageIndices = &imageIndex;
	presentInfo.pResults = nullptr; // Optional

	result = vkQueuePresentKHR(presentQueue, &presentInfo);
	if (result == VK_ERROR_OUT_OF_DATE_KHR || result == VK_SUBOPTIMAL_KHR || framebufferResized) {
		framebufferResized = false;
		recreateSwapchain();
		if (minimizedWindowNeedClose) {
			return;
		}
	}
	else if (result != VK_SUCCESS) {
		throw MakeErrorInfo("Failed to present swapchain image!");
	}

	currentFrame = (currentFrame + 1) % MAX_FRAMES_IN_FLIGHT;
}

Why is this happening and how to fix it?