guest - flak
Flaakle

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.so

Inspecting 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 directory

Which 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
    1184

After 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 directory

Finally 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 unavailable

We 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 unavailable

poll 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
    1878

How does that compare to chrome?

grep CALL.*gettime chromeflak.log | wc -l                                                
   14940

Chrome 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 unavailable

Actually, 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/0x1000

We 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.

Posted 2016-06-03 14:48:57 by tedu Updated: 2016-06-03 14:48:57
Tagged: software