GSoC ’14 Progress

It’s been way too long since my last blog post. Progress since then:

  • Async logging has finally landed after a long period of tree closures and bustages. If you’re running a recent nightly (which are only available for OS X and Windows at the moment), your logs will be logged asynchronously.
  • Log indexing calls for controlling a log file’s size. We decided on the scenarios under which a log file should be split, and a patch for it is awaiting review in bug 1025522.
  • Florian gave me feedback comments for my log indexing WIP. I’ve addressed a number of issues he pointed out and some bugs I found myself, and uploaded a new patch to bug 955014. I hope this can land soon after review iterations, and am excited for easily searchable logs (finally!).

I’m now working on infinite scroll:

  • First step is to add the ability to prepend a message instead of appending.
  • After that’s done, I’ll look into how messages are added to the UI when a conversation is restored from hold. Currently they’re added oldest to newest. This needs to be reversed – add the newest message first, then prepend the older ones.
  • The above allows for showing only the latest few messages, and keeping the rest in memory – these can be prepended as the user scrolls up – setting the stage for true infinite scroll.
  • Finally, fetch messages from the logs and prepend these as the user scrolls further. This step of course is a lot more complicated than I just described, I’ll be blogging about it as I get to it.

It’s worth mentioning that in between blog posts, midterm evaluations happened, and I passed – thank you aleth and the Instantbird team!

I should also acknowledge that I’m behind schedule and need to work faster if I want to do justice to the second half of my proposal.

Until next time!

GSoC ’14 Progress

Another week has passed and midterm evaluations are around the corner!
I’ve pushed the async log patch to try and uncovered a bug with the tests – but haven’t been able to fully debug this due to tree bustages and the weekend keeping me busy with other stuff.
While awaiting try builds and so on, I worked on log indexing, and wrote the basic UI for the log viewer (a big search bar at the top). Log searching works, and is fast!

In other news, I got to meet my fellow Instantbird GSoC students Saurabh and Mayank today! Writing this on the way back, in fact.

That’s all for now, I think. Cheers!

GSoC ’14 Progress

Here’s what I’ve done over the last week:

  • Review iterations for the async logs bug.
  • Wrote a log-indexing module that sweeps the logs and indexes them, and runs a basic benchmark on search. I was able to query single words at about ~10ms per ~1k results.
  • Had some discussions on the implementation of log indexing, these are summarized here.
  • Wrote a patch to move the log sweeping code currently residing in the stats service to logger.js, to be accessed via the logs service. (bug 1025464)

The async logs patch is nearly r+ (as is the patch that moves the log sweeping code). After it is, I’ll be pushing to try and making sure tests pass, and it’ll be good to go. As detailed in the etherpad, I’ll then be making use of the log sweeping code to index all logs, and add a method to query the index. The log viewer UI will be updated (likely an awesometab-esque search bar at the top), and there’ll be easily searchable logs for everyone :)

GSoC ’14 Progress

It’s been over a week since my last post, and my recollection of work done is a bit hazy :(. Here’s a quick summary though:

  • Tests! I’ve written pretty comprehensive tests for writing and reading of log files (including grouped-by-day reading). I learned about Assert.jsm – something so new that my tests broke one fine day because of ongoing changes in m-c (I expected it to be stable because do_check_* had already been marked deprecated in MDN).
  • Bug fixing. Writing tests uncovered several intricacies that have now been taken care of. One discovery that hasn’t been addressed yet is that if queued file operations exist during AsyncShutdown, they fail because stuff like JSON (and even dump) get removed from the scope. A simple (pending) solution is to yield on all of them when the “prpl-quit” notification is fired.
  • Thunderbird! I got a Thunderbird build running and tested the new API changes. The UI is properly listing and displaying logs. Gloda indexing has also been updated: I had to implement yet another promise queue to make sure we read only one conversation at a time (and not load all of them into memory). Debugging was a hassle and took ages: Components.utils.reportError is disabled from chrome code by default in Thunderbird! I searched around for hours to see why my code wasn’t being called when indeed it was – just that the reportError call was never firing.
  • In the middle of all this, I took a day to play with the convbrowser code to see if I could manipulate the way messages are added and so on. I succeeded in getting messages to be added in reverse, but bubbles grouping wasn’t working and my code got messy enough that I reverted everything. It was a good experiment though, a kind of warm-up exercise for the real task that looms ahead ;)
  • I also spotted and fixed a couple of minor miscellaneous bugs.

While the async-logs patches undergo review cycles, I plan to either play more with the convbrowser and churn out something concrete (my first goal is to make context messages load from the bottom up), or to start messing with databases – test out storage/retrieval performance and disk usage with full-text-search enabled if we store all messages in it for example. Maybe both!

Until next time! Hopefully the next progress update won’t take as long as this one did.

GSoC ’14 Progress: File I/O Performance and Promise Chains

In my last post I included a to-do list of sorts that I expected to complete before writing the next one. None of the items in the list have been crossed off, but the progress over the last couple of days call for another post so here goes.

First off: file I/O strategies. I had a few enlightening discussions on #perf with Yoric and avih about the strategy I proposed about log writing and file I/O in general. The strategy – having an OS.File instance open and repeatedly appending to it using write() – was deemed feasible, but then I started thinking about a problem Florian hinted – what happens when we try to read a log file that’s currently open for writing (and possibly during a pending write)?

I talked to Yoric about possible race conditions between reads and writes, and it turns out this isn’t a problem because OS.File does I/O on a single thread. However, he warned me that opening a file for reading while it was already open for writing might fail on Windows (in general, opening a file twice concurrently).

As a solution to this, I proposed that, instead of keeping the file open, we open it, write to it, and close it immediately whenever we need to append a message. Not keeping the file open means that we don’t have to worry about opening it twice simultaneously, but now I had to worry about overhead added from opening and closing the file every time. What would the impact be if, for example, 50 conversations were open and each of them had up to 30 incoming messages per second? Would the overhead added by opening/closing visibly impact performance in this kind of a situation?

I asked about this on #perf again, and this time avih responded with some valuable insight. He explained that OSes cache opens and closes (and even seeks) so that successively opening a file would cause negligible overhead. This was of course only considering OS level file handling, not counting overhead caused by the OS.File implementation.

Now that I was confident that opening/closing the file every time wasn’t totally insane, I wrote a small benchmark to compare performance between the two strategies for appending a string to a file 1000 times. I ran it on my MacBook’s SSD, a FAT32 USB 2 flash drive, and a HFS+ partition on my USB 3 hard drive. The results were similar: opening/closing the file every time was about 3-4 times slower than keeping it open (absolute values were between 0.5-1.5 seconds keeping it open, and 1.5-5 seconds opening/closing every time).

However, that was for 1000 consecutive writes – not likely in a realistic scenario, and even so, decent enough to go unnoticed by a user. As avih put it, “optimization is great, but if applied where it’s not really needed, then it just adds code and complexities overheads, but giving you nothing meaningful in return”. Of course, Florian might have something to say about it when he’s back ;)

With the strategy decided, I set about adapting the code accordingly, and realized it was still possible for a read to be called on a file during a pending write. I needed a queue system to ensure all operations on a given file happened one after another. Since all OS.File operations are represented by promises, I decided to map each file path to the promise for the ongoing operation on it. Then to queue an operation on a file, do the operation in the existing promise’s then. Here’s some code to make that clear:

let gFilePromises = new Map();

function queueFileOperation(aPath, aOperation) {
  // If there's no promise existing for the
  // given path already, set it to a
  // dummy pre-resolved promise.
  if (!gFilePromises.has(aPath))
    gFilePromises.set(aPath, Promise.resolve());

  let promise = gFilePromises.get(aPath).then(aOperation);
  gFilePromises.set(aPath, promise);
  return promise;
}

Now whenever I have to do any file operation, I just do |queueFileOperation(path, () => OS.File.foo(path, bar, …));| and presto! An async file I/O queue.

An interesting side effect of the above code snippet is that once a path is added to the map, it’s never removed (=memory leak). This is solved by a slight modification:

function queueFileOperation(aPath, aOperation) {
[...]
  let promise = gFilePromises.get(aPath).then(aOperation);
  gFilePromises.set(aPath, promise);
  promise.then(() => {
    // If no further operations have been
    // queued, remove the reference from the map.
    if (gFilePromises.get(aPath) == promise)
      gFilePromises.delete(aPath);
  });
  return promise;
}

And that’s about it! Long post, but it was a great learning experience for me and I figured it deserved one.

Cheers!

GSoC ’14 Progress: Async logger.js

Since my last post, I’ve made considerable progress in the quest to make file I/O async in logger.js.

  • I wrote some xpcshell tests for the log writing code, and tested it in a live Instantbird instance – it was good to go with a couple of minor mistakes in code.
  • Log reading is now also async, and the Instantbird log viewer has been updated for the API changes.
  • I’ve added error handling throughout. This is important because errors in Promises may be dropped to the floor if the Promise’s consumer doesn’t handle rejections, and especially in Promise chains where errors need to be propagated.
  • I had to figure out how to pass a Promise through an XPCOM interface. Turns out the return type needs to be declared as “jsval”.

All of this has been tested with the Instantbird log viewer and everything seems to be working smoothly. Coming up next:

  • The strategy I’m using for writing log files is to have an OS.File instance open and repeatedly append to it using write(). The file needs to be closed after arbitrary periods of inactivity.
  • Tests! Now that log reading is async, I need to write tests for writing/reading a conversation.
  • Other consumers of the imILogger API need to be updated (Thunderbird).

My next post will likely be when the items on the to-do list above have been crossed off. Until then, you can follow the progress of this effort on bug 955292.

GSoC ’14 Progress: Tasks and Promises

My semester finally finished last week, and we decided that a good way to start off my project would be to make chat history logging asynchronous. The current implementation in logger.js maintains an output stream to an nsIFile instance and synchronously writes to it. My job is to rewrite the relevant code using the OS.File API to make everything async.

Over the last couple of days, I’ve been researching on the Promise API and how it works with OS.File for async I/O. I learned how Task.js allows for clean code using the yield keyword, and sat around a lot pondering about preservation of sequence when working with async functions.

Things became clear once I realized that in Task.spawn(), what |yield <Promise>| was doing was simply letting the event loop continue until the Promise resolved.

I then proceeded to properly start rewriting the code (several failed attempts preceded my yield realization) for Conversation and System logs. I’ve attached a WIP to bug 955292 for feedback. The code is untested however, and my next task will be to write xpcshell tests to make sure everything is working.