I’ve been working on writing a Virtual KMS driver this past two months (with other cool people from the DRM community) and I was planning to write a post to explain VKMS, but that is taking me so much time since I need to write a pre-post to explain the DRM Subsystem first.
Thus, I have decided to write a small note to explain the iterative work process and the tools that helps me along the way.
VKMS is new a module to the DRM Subsystem that is underdevelopment in the drm-misc repository [1]
We have been using the IGT Test suit
[2]
to help us in adding new functionality to the VKMS and test its correctness.
I have been asigned to work on adding CRC support to the VKMS with the goal to pass the
kms_pipe_crc_basic test in the IGT test suit.
I am almost done from adding the basic CRC support and I am currently waiting for feedback on my patch
[3].
In the meanwhile, I’m working to extend the VKMS to pass CRC test with cursor support.
Since I’m pretty new to the DRM Subsystem, I’ve been using trial and error approach for VKMS development. The following script helps to give me a feedback on what went wrong when running the IGT test which allows me to identify where in the code I should fix.
$ cat trace.sh # trace.sh - need root priviliges modprobe -r vkms # in case vkms was loaded before modprobe vkms # to enable Ftrace to find its symbols for filtering echo 0x3f > /sys/module/drm/parameters/debug # to enable all log messages from drm cd /sys/kernel/debug/tracing echo 0 > tracing_on # disable tracing echo function_graph > current_tracer echo drm* > set_ftrace_filter # only record sys calls with 'drm' prefix echo vkms* >> set_ftrace_filter # append another filter with '>>' echo > trace # to clean the tracing log echo 1 > tracing_on # enable tracing again rm ~/trace.log # remove old tracing log cat trace_pipe | tee ~/trace.log # wait for sys calls with drm and vkms prefix
We need first to load the vkms module to enable Ftrace to find its symbols for filtering.
The drm module has different levels of debug messages which can be found in drm_print.h.
To enable all messages we need to set drm.debug = 0x3f, which can be done at run-time
by echoing the value to /sys/module/drm/parameters/debug.
The rest uses Ftrace to record the function calls that start with either drm or vkms
using the function_graph tracer and log it in trace.log.
To start debugging, we need to run the script first:
$ sudo su $ sh ~/trace.sh
Then on a separate terminal, run the IGT kms_cursor_crc test:
$ ./igt-gpu-tools/scripts/run-tests.sh -t kms_cursor_crc Found test list: "/home/haneen/git/igt-gpu-tools/build/tests/test-list.txt" [45/45] fail: 45 Thank you for running Piglit! Results have been written to /home/haneen/git/igt-gpu-tools/results
The test kms_cursor_crc has many subtests within it which you can check with
--list-subtest option as follow:
$ ./tests/kms_cursor_crc --list-subtest cursor-size-change cursor-64x64-onscreen cursor-64x64-offscreen cursor-64x64-sliding cursor-64x64-random cursor-64x64-dpms cursor-64x64-suspend cursor-64x64-rapid-movement ...
It appears that all the tests are failing. To isolate the problem, it is easier to focus on one test.
We can run cursor-size-change subtest from the kms_cursor_crc test
using the --debug option and --force-module that has been added recently
by Rodrigo Siqueria to enable the IGT to choose a specific module to run the tests on it
[4].
$ ./tests/kms_cursor_crc --run-subtest cursor-size-change --debug --force-module vkms
With that we get the following feedback:
**** END **** Subtest cursor-size-change: FAIL (0.247s) (kms_cursor_crc:5550) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=64, height=65, format=0x34325241, tiling=0x0, size=0) (kms_cursor_crc:5550) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=256) (kms_cursor_crc:5550) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=64, height=22, format=0x34325241, tiling=0x0, size=0) (kms_cursor_crc:5550) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=256) (kms_cursor_crc:5550) igt_fb-CRITICAL: Test assertion failure function igt_create_fb_with_bo_size, file ../lib/igt_fb.c:866: (kms_cursor_crc:5550) igt_fb-CRITICAL: Failed assertion: (drmModeAddFB2(fd, width, height, format, handles, pitches, fb->offsets, &fb_id, 0)) == 0 (kms_cursor_crc:5550) igt_fb-CRITICAL: Last errno: 22, Invalid argument Stack trace: #0 [__igt_fail_assert+0x180] #1 [igt_create_fb_with_bo_size+0x324] #2 [igt_create_fb+0x41] #3 [igt_create_color_fb+0x4c] #4 [create_cursor_fb+0x7c] #5 [run_test_generic+0x5cf] #6 [__real_main716+0x2d5] #7 [main+0x44] #8 [__libc_start_main+0xe7] #9 [_start+0x2a] Test kms_cursor_crc failed. **** DEBUG ****
The IGT test feedback shows that drmModeAddFB2 has failed.
We can check Ftrace and dmesg log files to get more details and understand why the function fails.
Ftrace is helpful for getting an overview of the test’s functions calls,
in this case, since the function fails early,
it does not give valuable feedback other than that the function failed @drm_internal_framebuffer_create,
but in different cases, like to understand how the atomic commit works,
I’ve found it really helpful.
# part of trace.sh
1) | drm_ioctl [drm]() {
1) 0.152 us | drm_dev_enter [drm]();
1) 0.150 us | drm_dev_exit [drm]();
1) 2.498 us | drm_dbg [drm]();
1) | drm_ioctl_kernel [drm]() {
1) 0.130 us | drm_dev_enter [drm]();
1) 0.101 us | drm_dev_exit [drm]();
1) 0.036 us | drm_ioctl_permit [drm]();
1) | drm_mode_addfb2 [drm]() {
1) | drm_internal_framebuffer_create [drm]() {
1) 2.570 us | drm_dbg [drm]();
1) 2.934 us | }
1) 3.334 us | }
1) 4.951 us | }
1) 2.106 us | drm_dbg [drm]();
1) + 11.993 us | }
After that, we can check dmesg logs. Enabling the drm to print all debug messages allow us to see the ioctl calls to drm and their arguments and return values as well.
$ dmesg | grep -A 3 DRM_IOCTL_MODE_ADDFB2 [drm:return_to_handler] pid=2759, dev=0xe200, auth=1, DRM_IOCTL_MODE_ADDFB2 [drm:return_to_handler] bad framebuffer height 22, should be >= 32 && <= 8192 [drm:return_to_handler] pid=2759, ret = -22 [IGT] kms_cursor_crc: exiting, ret=99
Upon checking the drm_internal_framebuffer_create in drm_framebuffer.c
we can see that the passed height value is less than config->min_height
So all we need to do is find where min_height is updated and change that value,
which happens to be during the initialization step of vkms.
After updating min_height and running kms_cursor_crc test again,
we can see now we have progressed a little bit and the
test skip 33 and fail 12 tests.
$ ./scripts/run-tests.sh -t kms_cursor_crc Found test list: "/home/haneen/git/igt-gpu-tools/build/tests/test-list.txt" [45/45] skip: 33, fail: 12 Thank you for running Piglit! Results have been written to /home/haneen/git/igt-gpu-tools/results
When repeating the above steps again after fixing the error, the log messages gives the next clue that I can use to advance VKMS a little bit again:
Invalid pixel format AR24 little-endian (0x34325241), modifier 0x0
Refrences:
[1] [drm-misc] drm/vkms: Introduce basic VKMS driver
[2] IGT GPU Tools - git repository