Description of problem: The events_trace tracer on i386 gives bad parameters to syscalls. This is due to a couple of things. One is that the sys_call interface needs to use the assmebly linked annotation, and the other is that the edx register is used before it is stored on the stack. Expect two patches to follow.
Created attachment 311623 [details] fix event tracer function annotations This patch fixes the function annotations of the event trace. The main fix is adding asmlinkage annotation to the sys_call function to give the syscalls in the event trace correct parameter recording on i386.
Created attachment 311624 [details] use passed in edx register on i386 The edx register on i386 was being used after SAVE_ALL, so the wrong data was being passed as the third parameter to the event tracer.
Added to -88
Difficult to say if this one is really fixed or not. Tested on RHEL/32 with 2.6.24.7-81.el5rt and 2.6.24.7-81.el5rt The following test program was used: ---------------------------------------------------- int main() { int fd; char *data = "0123456789"; char buf[20]; fd = open("test.file", O_CREAT | O_RDWR, 0660); write(fd, data, 10); lseek(fd, 0, SEEK_SET); read(fd, &buf, 10); close(fd); fprintf(stderr, "data = %lx\n", s); fprintf(stderr, "buf = %lx\n", &buf); return 0; } ---------------------------------------------------- The test was executed with: # trace-cmd -e -l -f ./tracetest > test.log For the -81 kernel, it was not possible to find much information about the different calls, as they were missing reference points to the code. # grep tracetes test-81.log | grep "sys_read (" tracetes-4278 7.... 36775us : sys_read (syscall_call) tracetes-4278 7.... 38010us : sys_read (syscall_call) # grep tracetes test2-81.log | grep "sys_write (" tracetes-4278 7.... 37918us : sys_write (syscall_call) tracetes-4278 7.... 38348us : sys_write (syscall_call) tracetes-4278 7.... 38395us : sys_write (syscall_call) For the -93 kernel, more information was found ... but seems to be some wrong formatting. The output of the test program running on -93 kernel was: ----------------------- data = 8048640 buf = bf855298 ----------------------- Trace logs shows ... # grep tracetes test-93.log | grep "sys_read (" tracetes-4055 4.... 46586us : system_call sys_read (3 bf854ae8 bf854ae8) tracetes-4055 4.... 46588us : sys_read (syscall_call) tracetes-4055 4.... 56132us : sysenter_enter sys_read (3 bf855298 bf855298) tracetes-4055 4.... 56134us : sys_read (syscall_call) # grep tracetes test2-93_2.log | grep "sysenter_enter" tracetes-4055 5.... 36831us : sysenter_enter sys_execve (bf9cbbf6 bf9c9cb4 bf9c9cb4) tracetes-4055 4.... 47643us : sysenter_enter sys_open (804864b 42 42) tracetes-4055 4.... 47797us : sysenter_enter sys_write (3 8048640 8048640) tracetes-4055 4.... 56125us : sysenter_enter sys_lseek (3 0 0) tracetes-4055 4.... 56132us : sysenter_enter sys_read (3 bf855298 bf855298) tracetes-4055 4.... 56165us : sysenter_enter sys_close (3 bf855298 bf855298) tracetes-4055 4.... 56350us : sysenter_enter sys_write (2 bf852b78 bf852b78) tracetes-4055 4.... 56416us : sysenter_enter sys_write (2 bf852b78 bf852b78) tracetes-4055 4.... 56624us : sysenter_enter sys_exit_group (0 4 4) Here the 2nd and 3rd parameter logged is identical, which I believe is wrong. But the first sys_write matches the address to *data. While the first sys_read matches the address to &buf.
Created attachment 325706 [details] fix parameter passing for i386 event system call tracer The parameter index of the stack to retrieve the third parameter was wrong. The SAVE_ALL code pushes the parameters in as: push edx push ecx push ebx But it modifies edx before we get to the sys_call call. So we need to retrieve edx. But we also need to save it to its original value and we push it too. push edx move 8(esp), edx The problem here is that, after the push edx, the index went from 8 to 12.
The problem davids found in testing is i386 only. BZ474683 was created to track the new i386 problem and the fix in Comment #6 (on 2008-12-04) will be targeted for the 1.1.1 release. The fix in BZ455095 will remain in the 1.1 release.
Moved to verified, as the extra patch needed will be implemented in a later release. This patch is found in bug #474683. Even though, this bug is not completely fixed, it is after all an improvement from the MRG-1.0.3 release (-81 kernel). And it is definitely not a regression.
An advisory has been issued which should help the problem described in this bug report. This report is therefore being closed with a resolution of ERRATA. For more information on therefore solution and/or where to find the updated files, please follow the link below. You may reopen this bug report if the solution does not work for you. http://rhn.redhat.com/errata/RHSA-2009-0009.html