browser ktrace browsing
The key to understanding how modern browsers work is to observe them in action. For this, we can use ktrace. I’ve posted a few ktrace snippets before, but here’s some new ones to aid in our understanding. Even if we don’t learn anything, deciphering ktrace and kdump output is a pretty useful skill. I use ktrace to verify software I write does what I think I expect. Using ktrace on other people’s software is like a never ending set of practice exercises.
All of the kdump output below has the same form. Process and thread ID, name, timestamp, record type, data.
On the surface, Firefox looks like a pretty simple program with few dependencies:
ldd /usr/local/bin/firefox
/usr/local/bin/firefox:
Start End Type Open Ref GrpRef Name
0000110435b00000 0000110435f24000 exe 2 0 0 /usr/local/bin/firefox
0000110697489000 00001106979b7000 rlib 0 1 0 /usr/local/lib/libestdc++.so.17.0
00001106ce27d000 00001106ce6a5000 rlib 0 2 0 /usr/lib/libm.so.9.0
0000110703163000 0000110703571000 rlib 0 1 0 /usr/lib/libpthread.so.22.0
000011065367e000 0000110653b47000 rlib 0 1 0 /usr/lib/libc.so.87.0
00001106f8f00000 00001106f8f00000 rtld 0 1 0 /usr/libexec/ld.soInspecting the log reveals a different story.
grep NAMI.*/usr.*/lib/.*[.]so firefox.log
35327/1035327 firefox 0.008957 NAMI "/usr/local/lib/firefox-46.0.1/libxul.so.64.0"
35327/1035327 firefox 0.009660 NAMI "/usr/local/lib/firefox-46.0.1/liblgpllibs.so.64.0"
35327/1035327 firefox 0.010472 NAMI "/usr/local/lib/firefox-46.0.1/libmozsqlite3.so.64.0"
35327/1035327 firefox 0.011462 NAMI "/usr/local/lib/firefox-46.0.1/libmozgtk.so.64.0"
35327/1035327 firefox 0.011784 NAMI "/usr/local/lib/libgdk-3.so.2000.3"
35327/1035327 firefox 0.012072 NAMI "/usr/local/lib/libgtk-3.so.2000.3"
35327/1035327 firefox 0.012884 NAMI "/usr/X11R6/lib/libfreetype.so.24.1"
35327/1035327 firefox 0.013196 NAMI "/usr/X11R6/lib/libXcomposite.so.4.0"
35327/1035327 firefox 0.013505 NAMI "/usr/local/lib/libdbus-1.so.11.1"
35327/1035327 firefox 0.013847 NAMI "/usr/local/lib/libglib-2.0.so.4200.3"
35327/1035327 firefox 0.014122 NAMI "/usr/X11R6/lib/libXrandr.so.7.1"
35327/1035327 firefox 0.014435 NAMI "/usr/local/lib/libpng.so.17.2"
35327/1035327 firefox 0.014737 NAMI "/usr/X11R6/lib/libpthread-stubs.so.2.0"
35327/1035327 firefox 0.015022 NAMI "/usr/local/lib/libintl.so.6.0"
...And so on, for a total of about 80 libraries. If we audit them at the rate of one per week, we’ll be done in less than two years. (Not counting any of the gstreamer libraries, which may get loaded later on demand to play assorted media.)
If we peek at another browser, chrome, we can see some other interesting file behavior.
57686/1012949 chrome 0.360459 CALL access(0x3ea65a45d40,0<F_OK>)
57686/1012949 chrome 0.360553 NAMI "/home/tedu/.pki/nssdb/.15412817_dOeSnotExist_.db"
57686/1012949 chrome 0.360657 RET access -1 errno 2 No such file or directory
57686/1012949 chrome 0.360664 CALL clock_gettime(CLOCK_MONOTONIC,0x3ea40c7c980)
57686/1012949 chrome 0.360683 CALL access(0x3ea65a45d40,0<F_OK>)
57686/1012949 chrome 0.360694 NAMI "/home/tedu/.pki/nssdb/.15412818_dOeSnotExist_.db"
57686/1012949 chrome 0.360701 RET access -1 errno 2 No such file or directory
57686/1012949 chrome 0.360704 CALL clock_gettime(CLOCK_MONOTONIC,0x3ea40c7c980)
57686/1012949 chrome 0.360711 CALL access(0x3ea65a45d40,0<F_OK>)
57686/1012949 chrome 0.360714 NAMI "/home/tedu/.pki/nssdb/.15412819_dOeSnotExist_.db"
57686/1012949 chrome 0.360722 RET access -1 errno 2 No such file or directoryWhich db that doesn’t exist should we open? All of them! (In a pattern that will repeat everywhere, each access call is accompanied by a call to clock_gettime. How can we know how much time we’re wasting if we don’t measure it?)
And so on and so forth...
grep /nssdb.*dOeSnotExist_ chrome.log | wc -l
1184After exhausting the possibilities of the nssdb directory, we move on to another promising location.
57686/1012949 chrome 0.366604 NAMI "/var/tmp/.15411734_dOeSnotExist_.db"
57686/1012949 chrome 0.366657 NAMI "/var/tmp/.15411735_dOeSnotExist_.db"
57686/1012949 chrome 0.366723 NAMI "/var/tmp/.15411736_dOeSnotExist_.db"
57686/1012949 chrome 0.366798 NAMI "/var/tmp/.15411737_dOeSnotExist_.db"
57686/1012949 chrome 0.366852 NAMI "/var/tmp/.15411738_dOeSnotExist_.db"
57686/1012949 chrome 0.366892 NAMI "/var/tmp/.15411739_dOeSnotExist_.db"
... 1000 lines elided for brevity ...
57686/1012949 chrome 0.398973 NAMI "/var/tmp/.15412798_dOeSnotExist_.db"
57686/1012949 chrome 0.398988 NAMI "/var/tmp/.15412799_dOeSnotExist_.db"Having reached the end, let’s do it again. Just in case we missed something the first time.
57686/1012949 chrome 0.400200 NAMI "/var/tmp/.15411768_dOeSnotExist_.db"
57686/1012949 chrome 0.400212 NAMI "/var/tmp/.15411769_dOeSnotExist_.db"
57686/1012949 chrome 0.400225 NAMI "/var/tmp/.15411770_dOeSnotExist_.db"
... another 1000 lines elided ...
57686/1012949 chrome 0.432872 NAMI "/var/tmp/.15412737_dOeSnotExist_.db"
57686/1012949 chrome 0.432895 NAMI "/var/tmp/.15412738_dOeSnotExist_.db"
57686/1012949 chrome 0.432934 NAMI "/var/tmp/.15412739_dOeSnotExist_.db"
57686/1012949 chrome 0.432988 NAMI "/var/tmp/.15412740_dOeSnotExist_.db"To be precise, only 973 filenames are checked twice. 93 unique names are checked a single time.
Back to firefox, it appears to have an unhealthy obsession with looking around for its rival.
35327/1035327 firefox 1.183453 CALL access(0x15d7bc25c185,0x1<X_OK>)
35327/1035327 firefox 1.183455 NAMI "/home/tedu/bin/chrome"
35327/1035327 firefox 1.183461 RET access -1 errno 2 No such file or directory
35327/1035327 firefox 1.183462 CALL access(0x15d7bc25c18f,0x1<X_OK>)
35327/1035327 firefox 1.183464 NAMI "/bin/chrome"
35327/1035327 firefox 1.183466 RET access -1 errno 2 No such file or directory
35327/1035327 firefox 1.183468 CALL access(0x15d7bc25c18e,0x1<X_OK>)
35327/1035327 firefox 1.183469 NAMI "/sbin/chrome"
35327/1035327 firefox 1.183472 RET access -1 errno 2 No such file or directory
35327/1035327 firefox 1.183473 CALL access(0x15d7bc25c18b,0x1<X_OK>)
35327/1035327 firefox 1.183475 NAMI "/usr/bin/chrome"
35327/1035327 firefox 1.183479 RET access -1 errno 2 No such file or directory
35327/1035327 firefox 1.183480 CALL access(0x15d7bc25c18a,0x1<X_OK>)
35327/1035327 firefox 1.183482 NAMI "/usr/sbin/chrome"
35327/1035327 firefox 1.183485 RET access -1 errno 2 No such file or directory
35327/1035327 firefox 1.183486 CALL access(0x15d7bc25c185,0x1<X_OK>)
35327/1035327 firefox 1.183488 NAMI "/usr/X11R6/bin/chrome"
35327/1035327 firefox 1.183491 RET access -1 errno 2 No such file or directoryFinally we find a match, at which point we call stat.
35327/1035327 firefox 1.183493 CALL access(0x15d7bc25c185,0x1<X_OK>)
35327/1035327 firefox 1.183494 NAMI "/usr/local/bin/chrome"
35327/1035327 firefox 1.183498 RET access 0
35327/1035327 firefox 1.183499 CALL getuid()
35327/1035327 firefox 1.183501 RET getuid 1000<"tedu">
35327/1035327 firefox 1.183502 CALL stat(0x15d7bc25c185,0x7f7fffff28b0)
35327/1035327 firefox 1.183504 NAMI "/usr/local/bin/chrome"And then... nothing. Until next time. An entire 1.5 seconds has elapsed. Perhaps I have installed chrome in a new location. Let’s check again.
35327/1035327 firefox 2.565863 CALL access(0x15d7bd822285,0x1<X_OK>)
35327/1035327 firefox 2.565866 NAMI "/home/tedu/bin/chrome"
35327/1035327 firefox 2.565873 RET access -1 errno 2 No such file or directory
35327/1035327 firefox 2.565875 CALL access(0x15d7bd82228f,0x1<X_OK>)
35327/1035327 firefox 2.565877 NAMI "/bin/chrome"
35327/1035327 firefox 2.565880 RET access -1 errno 2 No such file or directory
35327/1035327 firefox 2.565881 CALL access(0x15d7bd82228e,0x1<X_OK>)
35327/1035327 firefox 2.565883 NAMI "/sbin/chrome"Nope, chrome is right where I left it. But no reason to give up hope.
35327/1035327 firefox 4.029638 CALL access(0x15d878812285,0x1<X_OK>)
35327/1035327 firefox 4.029640 NAMI "/home/tedu/bin/chrome"
35327/1035327 firefox 4.029648 RET access -1 errno 2 No such file or directory
35327/1035327 firefox 4.029650 CALL access(0x15d87881228f,0x1<X_OK>)
35327/1035327 firefox 4.029652 NAMI "/bin/chrome"I may not install and uninstall chrome every 1.5 seconds, but in case I do, firefox will be ready. Ever vigilant.
So far, we’re just getting started. What does a browser look like in the steady state?
Here’s a chunk of chrome’s event loop, cycling between poll and recvmsg.
57686/1057686 chrome 5.826846 CALL poll(0x3ea31e03f00,5,0)
57686/1057686 chrome 5.826867 RET poll 0
57686/1057686 chrome 5.826877 CALL recvmsg(11,0x7f7ffffefe80,0)
57686/1057686 chrome 5.826889 RET recvmsg -1 errno 35 Resource temporarily unavailable
57686/1057686 chrome 5.826953 CALL recvmsg(8,0x7f7ffffefe30,0)
57686/1057686 chrome 5.826964 RET recvmsg -1 errno 35 Resource temporarily unavailable
57686/1057686 chrome 5.826973 CALL recvmsg(11,0x7f7ffffefe40,0)
57686/1057686 chrome 5.826985 RET recvmsg -1 errno 35 Resource temporarily unavailable
57686/1057686 chrome 5.827019 CALL poll(0x3ea31e03f00,5,5)
57686/1057686 chrome 5.841924 RET poll 1
57686/1057686 chrome 5.841953 CALL recvmsg(11,0x7f7ffffefe80,0)
57686/1057686 chrome 5.841970 RET recvmsg -1 errno 35 Resource temporarily unavailable
57686/1057686 chrome 5.841991 CALL read(12,0x7f7ffffeffe0,0x2)
57686/1057686 chrome 5.842032 RET read 1
57686/1057686 chrome 5.842927 CALL write(27,0x7f7ffffed7b7,0x1)
57686/1057686 chrome 5.842946 RET write 1
57686/1057686 chrome 5.845307 CALL recvmsg(8,0x7f7ffffefe30,0)
57686/1057686 chrome 5.845351 RET recvmsg -1 errno 35 Resource temporarily unavailable
57686/1057686 chrome 5.845375 CALL recvmsg(11,0x7f7ffffefe40,0)
57686/1057686 chrome 5.845403 RET recvmsg -1 errno 35 Resource temporarily unavailable
57686/1057686 chrome 5.845429 CALL poll(0x3ea31e03f00,5,0)
57686/1057686 chrome 5.845527 RET poll 0
57686/1057686 chrome 5.845571 CALL recvmsg(11,0x7f7ffffefe80,0)
57686/1057686 chrome 5.845601 RET recvmsg -1 errno 35 Resource temporarily unavailableWe call poll, which returns 0 to indicate that there’s nothing to read. That’s ok, we’ll check anyway. First fd 11, then 8, then check fd 11 again just in case. Then it’s back to poll. Hey, this time we have some data. We will of course ignore the indicated fd while we check 11 first. Nope, no data. OK, let’s read from the ready fd, 12. Then we can check fds 8 and 11 again before calling poll. And so the cycle continues. (fd 8 is /tmp/.X11-unix/X0, the unix socket used to connect to the X server. fd 11 is... also /tmp/.X11-unix/X0, just a different opening.)
I’m picking on chrome, but a somewhat similar pattern can be observed in xterm, partially the result of libxcb.
40356/1040356 xterm 3.878666 CALL poll(0x7f7ffffcf450,1,0)
40356/1040356 xterm 3.878670 RET poll 0
40356/1040356 xterm 3.878674 CALL ioctl(3,FIONREAD,0x7f7ffffcf8fc)
40356/1040356 xterm 3.878686 RET ioctl 0
40356/1040356 xterm 3.878696 CALL recvmsg(3,0x7f7ffffcf4a0,0)
40356/1040356 xterm 3.878701 RET recvmsg -1 errno 35 Resource temporarily unavailable
40356/1040356 xterm 3.878704 CALL recvmsg(3,0x7f7ffffcf4a0,0)
40356/1040356 xterm 3.878708 RET recvmsg -1 errno 35 Resource temporarily unavailable
40356/1040356 xterm 3.878711 CALL poll(0x7f7ffffcf450,1,0)
40356/1040356 xterm 3.878715 RET poll 0
40356/1040356 xterm 3.878717 CALL ioctl(3,FIONREAD,0x7f7ffffcf8fc)
40356/1040356 xterm 3.878721 RET ioctl 0
40356/1040356 xterm 3.878725 CALL recvmsg(3,0x7f7ffffcf4a0,0)
40356/1040356 xterm 3.878747 RET recvmsg -1 errno 35 Resource temporarily unavailable
40356/1040356 xterm 3.878750 CALL recvmsg(3,0x7f7ffffcf4a0,0)
40356/1040356 xterm 3.878754 RET recvmsg -1 errno 35 Resource temporarily unavailablepoll says there is nothing to read, but in case that’s incorrect, we call ioctl(FIONREAD) to see how many bytes are available. None, of course, but in case that’s incorrect, let’s just skip ahead and try reading anyway. Twice. Then we’ll go back to poll to see if anything has changed. Layers upon layers of efficient event driven programming.
The code in xterm and its libraries is a little easier to wade through. Different layers of abstraction each want to perform some operation, but since they aren’t connected to the same event loop, they have to fake it with no timeout polling. This results in many redundant system calls as information about the state of a socket fails to pass from one layer to another.
Meanwhile, off in another chrome thread, another event loop cycles. This time we’ll use kevent.
57686/1012949 chrome 5.807951 CALL kevent(25,0x3ea7a1f2800,0,0x3ea09199000,64,0x3ea40c7de10)
57686/1012949 chrome 5.807966 STRU struct timespec { 0 }
57686/1012949 chrome 5.807978 RET kevent 0
57686/1012949 chrome 5.807991 CALL clock_gettime(CLOCK_MONOTONIC,0x3ea40c7de40)
57686/1012949 chrome 5.808023 CALL clock_gettime(CLOCK_MONOTONIC,0x3ea40c7dc38)
57686/1012949 chrome 5.808055 CALL clock_gettime(CLOCK_MONOTONIC,0x3ea40c7de40)
57686/1012949 chrome 5.808161 CALL kevent(25,0x3ea7a1f2800,0,0x3ea09199000,64,0x3ea40c7de10)
57686/1012949 chrome 5.808180 STRU struct timespec { 0 }
57686/1012949 chrome 5.808186 RET kevent 0
57686/1012949 chrome 5.808197 CALL clock_gettime(CLOCK_MONOTONIC,0x3ea40c7de40)
57686/1012949 chrome 5.808233 CALL clock_gettime(CLOCK_MONOTONIC,0x3ea40c7dc38)
57686/1012949 chrome 5.808267 CALL clock_gettime(CLOCK_MONOTONIC,0x3ea40c7dd68)
57686/1012949 chrome 5.808300 CALL clock_gettime(CLOCK_MONOTONIC,0x3ea40c7de80)
57686/1012949 chrome 5.808337 CALL clock_gettime(CLOCK_MONOTONIC,0x3ea40c7de40)
57686/1012949 chrome 5.808357 CALL clock_gettime(CLOCK_MONOTONIC,0x3ea40c7de40)
57686/1012949 chrome 5.808372 CALL kevent(25,0x3ea7a1f2800,0,0x3ea09199000,64,0x3ea40c7de10)kevent returns no work. We could call it again, but it’s more fun to watch paint dry. I mean the clock spin. Then after a suitable number of milliseconds have passed, we call kevent again. We could provide kevent with a nonzero timeout, but why burden the kernel with such heavy lifting when we can emulate it in userspace?
Two threads playing ping pong. At this level, it’s hard to see what they’re up to, only the consequences.
57686/1057686 chrome 4.842955 CALL __thrwakeup(0x3ea7200fc38,1)
57686/1057686 chrome 4.842957 RET __thrwakeup 0
57686/1057686 chrome 4.842959 CALL __thrsleep(0x3ea8bb744e0,CLOCK_REALTIME,0,0x3ea8bb74460,0)
57686/1053880 chrome 4.842962 RET __thrsleep 0
57686/1053880 chrome 4.842964 CALL __thrwakeup(0x3ea8bb744e0,1)
57686/1053880 chrome 4.842966 RET __thrwakeup 0
57686/1053880 chrome 4.842969 CALL __thrsleep(0x3ea7200fc38,CLOCK_REALTIME,0,0x3ea8bb74460,0)
57686/1057686 chrome 4.842971 RET __thrsleep 0
57686/1057686 chrome 4.842974 CALL __thrwakeup(0x3ea7200fc38,1)
57686/1057686 chrome 4.842976 RET __thrwakeup 0
57686/1057686 chrome 4.842978 CALL __thrsleep(0x3ea8bb744e0,CLOCK_REALTIME,0,0x3ea8bb74460,0)
57686/1053880 chrome 4.842981 RET __thrsleep 0
57686/1053880 chrome 4.842983 CALL __thrwakeup(0x3ea8bb744e0,1)
57686/1053880 chrome 4.842985 RET __thrwakeup 0
57686/1053880 chrome 4.842987 CALL __thrsleep(0x3ea7200fc38,CLOCK_REALTIME,0,0x3ea8bb74460,0)
57686/1057686 chrome 4.842990 RET __thrsleep 0
57686/1057686 chrome 4.842993 CALL __thrwakeup(0x3ea7200fc38,1)
57686/1057686 chrome 4.842996 RET __thrwakeup 0
57686/1057686 chrome 4.842998 CALL __thrsleep(0x3ea8bb744e0,CLOCK_REALTIME,0,0x3ea8bb74460,0)
57686/1053880 chrome 4.843000 RET __thrsleep 0
57686/1053880 chrome 4.843002 CALL __thrwakeup(0x3ea8bb744e0,1)How many system calls does it take to display a simple flak page, with no javascript or external resources? To establish a baseline, I ktraced both ftp and xterm. ftp will fetch the page, write it to the terminal, then xterm will display the file. Pretty crude as far as browsers go, but it covers all the necessary OS facilities for networking and graphic display.
cat ftpflak.log xterm.log | grep CALL | wc -l
1878How does that compare to chrome?
grep CALL.*gettime chromeflak.log | wc -l
14940Chrome checks the time approximately ten times more frequently than the total combined work of ftp and xterm. I won’t bore you with all the details of what it’s doing between time checks, but maybe we can examine the system calls related to the network connection. Once all the intermingled noise is removed, it’s almost half sane. (The following traces will be much more understandable if one remembers that kevent can be passed in a list of changes to watch for and also returns out a list of events that have occurred. It’s not unusual to see calls kevent in a row if the first has a nonzero change count (the third argument).)
12560/1068374 chrome 1.560401 CALL socket(AF_INET,0x1<SOCK_STREAM>,0x6)
12560/1068374 chrome 1.560430 RET socket 66/0x42
12560/1068374 chrome 1.560454 CALL fcntl(66,F_SETFL,0x6<O_RDWR|O_NONBLOCK>)
12560/1068374 chrome 1.560573 CALL connect(66,0x1152f900b200,16)
12560/1068374 chrome 1.560586 STRU struct sockaddr { AF_INET, 208.82.130.146:80 }
12560/1068374 chrome 1.560654 RET connect -1 errno 36 Operation now in progress
12560/1068374 chrome 1.560672 CALL clock_gettime(CLOCK_MONOTONIC,0x115241a78ac8)
12560/1068374 chrome 1.560701 CALL clock_gettime(CLOCK_MONOTONIC,0x115241a78a08)
12560/1068374 chrome 1.560730 CALL clock_gettime(CLOCK_MONOTONIC,0x115241a78b68)
12560/1068374 chrome 1.560774 CALL clock_gettime(CLOCK_MONOTONIC,0x115241a79888)
12560/1068374 chrome 1.560801 CALL clock_gettime(CLOCK_MONOTONIC,0x115241a7a518)
12560/1068374 chrome 1.560833 CALL clock_gettime(CLOCK_MONOTONIC,0x115241a7a9a8)
12560/1068374 chrome 1.560861 CALL clock_gettime(CLOCK_MONOTONIC,0x115241a7aa38)
12560/1068374 chrome 1.560937 CALL clock_gettime(CLOCK_MONOTONIC,0x115241a7ac68)
12560/1068374 chrome 1.560962 CALL clock_gettime(CLOCK_MONOTONIC,0x115241a7aa48)Create a socket, make it nonblocking, start connecting, and then “wait”. Eventually we will register this fd with kevent.
12560/1068374 chrome 1.561727 CALL kevent(25,0x115267ba9000,1,0x1152aeeaf800,64,0x115241a7ae40)
12560/1068374 chrome 1.561824 STRU struct kevent { ident=66, filter=EVFILT_WRITE, flags=0x1<EV_ADD>, fflags=0<>, data=0, udata=0x11529e67dd80 }A bit more waiting, as in 190 more clock_gettime calls, and then we finally give up and call kevent, passing it a timeout. That returns almost immediately, because while we were screwing around watching the clock, the kernel finished connecting our socket.
12560/1068374 chrome 1.583684 CALL kevent(25,0x115267ba9000,0,0x1152aeeaf800,64,0x115241a7ae40)
12560/1068374 chrome 1.583708 STRU struct timespec { 0.208389000 }
12560/1068374 chrome 1.584778 STRU struct kevent { ident=66, filter=EVFILT_WRITE, flags=0x1<EV_ADD>, fflags=0<>, data=17376, udata=0x11529e67dd80 }
12560/1068374 chrome 1.584816 RET kevent 1
12560/1068374 chrome 1.584851 CALL getsockopt(66,SOL_SOCKET,SO_ERROR,0x115241a7ada4,0x115241a7ada0)
12560/1068374 chrome 1.584868 RET getsockopt 0
12560/1068374 chrome 1.584891 CALL getsockname(66,0x115241a7aba8,0x115241a7aca8)kevent says we’re ready to go. We check for any errors during the async connect, hopefully none, and it’s time to write “GET /...”.
12560/1068374 chrome 1.588414 CALL kevent(25,0x115267ba9000,1,0x1152aeeaf800,64,0x115241a7ae40)
12560/1068374 chrome 1.588437 STRU struct kevent { ident=66, filter=EVFILT_WRITE, flags=0x2<EV_DELETE>, fflags=0<>, data=0, udata=0x0 }
12560/1068374 chrome 1.591417 CALL recvfrom(66,0x115241a7a977,0x1,0x2<MSG_PEEK>,0,0)
12560/1068374 chrome 1.591432 RET recvfrom -1 errno 35 Resource temporarily unavailable
12560/1068374 chrome 1.595063 CALL recvfrom(66,0x115241a7a857,0x1,0x2<MSG_PEEK>,0,0)
12560/1068374 chrome 1.595078 RET recvfrom -1 errno 35 Resource temporarily unavailable
12560/1068374 chrome 1.595398 CALL write(66,0x115240b46818,0x1b9)
12560/1068374 chrome 1.595478 RET write 441/0x1b9
12560/1068374 chrome 1.595598 CALL read(66,0x1152739ea000,0x1000)
12560/1068374 chrome 1.595611 RET read -1 errno 35 Resource temporarily unavailableActually, first we will unregister fd 66. Then we try peeking at it, twice for good measure, then we write. Then we read again before the server has had a chance to reply. At last, we’re ready to receive the response from the server.
12560/1068374 chrome 1.595676 CALL kevent(25,0x115267ba9000,1,0x1152aeeaf800,64,0x115241a7ae40)
12560/1068374 chrome 1.595692 STRU struct kevent { ident=66, filter=EVFILT_READ, flags=0x1<EV_ADD>, fflags=0x2<NOTE_EOF>, data=0, udata=0x1152c249e000 }
12560/1068374 chrome 1.615777 CALL kevent(25,0x115267ba9000,0,0x1152aeeaf800,64,0x115241a7ae40)
12560/1068374 chrome 1.625087 STRU struct kevent { ident=66, filter=EVFILT_READ, flags=0x1<EV_ADD>, fflags=0<>, data=1448, udata=0x1152c249e000 }
12560/1068374 chrome 1.625309 CALL read(66,0x1152739ea000,0x1000)
12560/1068374 chrome 1.625387 RET read 4096/0x1000We call kevent once to register for available reads, then again to check for reads. Read some data! Hurray HTML! We’ve read 4096 bytes, so the next thing we want to do is...
12560/1068374 chrome 1.626752 CALL kevent(25,0x115267ba9000,1,0x1152aeeaf800,64,0x115241a7ae40)
12560/1068374 chrome 1.626770 STRU struct kevent { ident=66, filter=EVFILT_READ, flags=0x2<EV_DELETE>, fflags=0<>, data=0, udata=0x0 }
12560/1068374 chrome 1.644986 CALL read(66,0x11525021d000,0x8000)
12560/1068374 chrome 1.645059 RET read 3326/0xcfe
12560/1068374 chrome 1.647122 CALL recvfrom(66,0x115241a7a2b7,0x1,0x2<MSG_PEEK>,0,0)
12560/1068374 chrome 1.647129 RET recvfrom -1 errno 35 Resource temporarily unavailable
12560/1068374 chrome 1.647137 CALL recvfrom(66,0x115241a79ad7,0x1,0x2<MSG_PEEK>,0,0)
12560/1068374 chrome 1.647142 RET recvfrom -1 errno 35 Resource temporarily unavailable
Delete fd 66 from the kqueue. Then we’ll read some more since we didn’t get everything the first time. And now that we’ve gotten it all, two more peeks just to confirm. Why we delete the fd from the kqueue in the middle of the read operation is anyone’s guess.
Hopefully as a result of this exercise the reader has gained some valuable insight into modern web browser design.
Tagged: software