Time to persist a set of keys from data load has increased.

Matt Ingenthron added a comment - 04/Jan/11 4:31 PM Bringing in some comments from email to this issue... Chiyoung Seo wrote: > > Hmm, that's actually opposite to the performance results that I observed in the WAL testing. I think one possible reason is the checkpoint operation (transferring all the write transactions appended in the WAL file back to the original database) takes much more time than we expected. > > > > Also, did the background fetch jobs interleave with persistence tasks? No, this is simply a data load test. From Keith:     persist time does include load time. so its empty server (start     timer) -> load keys -> wait for 100% persistence -> end timer I wouldn't expect the WAL file append to enter into it, but maybe it does. Keith: what triggers 100% persistence? I'm sure it's a stat... is it something like the todo dropping to 0? Is it possible that there's a state in between where we have things persisted to the log, but we're still considering it todo in stats? That would be good and could explain the nearly double.

Matt Ingenthron added a comment - 04/Jan/11 4:34 PM Chiyoung Seo wrote: > > I don't think this case is possible as we decrement the todo stat every time an item is persisted into the WAL file. As you know, we schedule a commit per 1000 writes, and a special record indicating a commit will be also appended in the WAL file. But the commit that causes the WAL file to be 1000 pages or more will trigger the checkpoint operation, and consequently its execution time will be much longer than other normal commits. So, since all of this is done off of the dispatcher and only in serial, it's possible then that this is really just a matter of the extra overhead to WAL. Before, persisting data consisted of writing a bunch of operations and committing, at which point they'd be in a stable place in the original datafile. After WAL, we write to the log, but that commit() portion (which we do much more often) takes longer. However, the time for that commit of data already on stable storage is on the IO dispatcher, so overall it takes longer to get it done. This would also mean that under system memory pressure (where we'd have less filesystem cached), it could be a lot longer since we'd have to re-read to write. Or is the WAL kept in memory as well? Perhaps it's tunable? Does this sound accurate? Would one way to test for this to be to increase the number of transactions between commits? I guess that should help, but wouldn't prove/disprove anything unless the loaded data fit in the number of transactions in a commit, since there is still the extra work.

Chiyoung Seo added a comment - 04/Jan/11 5:10 PM Before WAL, we used the "DELETE" journal mode that writes a copy of the original database content into a separate rollback journal file and then writes changes directly into the database file. A commit is executed when the rollback file is deleted. So, each write transaction requires two disk IO operations and each commit requires the rollback file to be removed. A commit was also scheduled by the dispatcher. On the other hand, WAL simply appends each write transaction to the WAL file, and a normal commit is also very fast as it is simply appended to the WAL file. But, the commit that triggers the checkpoint operation will have longer execution time, but not likely huge from my performance testing. So, the WAL mode shouldn't have much worse write performance than the DELETE mode. This is also what I observed from my testing. Let me sync up with Keith and investigate this issue to find out the main reason for this performance bottleneck.

Chiyoung Seo added a comment - 04/Jan/11 6:09 PM Matt, Keith, Which sqlite synchronous mode was used for load testing? Was "NORMAL" mode used in both 1.6.3 and 1.6.4? WAL will have worse performance if FULL mode is only used in 1.6.4.

Matt Ingenthron added a comment - 04/Jan/11 6:39 PM I'm not sure, Keith?

Keith Batten added a comment - 04/Jan/11 6:41 PM For 1.6.3 we used: PRAGMA journal_mode = TRUNCATE; PRAGMA synchronous = NORMAL; For 1.6.4.1 we used: PRAGMA journal_mode = WAL; PRAGMA read_uncommitted = 1; PRAGMA synchronous = NORMAL;

Chiyoung Seo added a comment - 05/Jan/11 1:44 PM I ran simple testing for write performance comparisons between WAL and TRUNCATE modes by inserting 2M items (2K size each) into one node cluster: 1) TRUNCATE mode, 250000 transaction size ep_commit_time_total: 30 ep_flush_duration_total: 131 2) WAL mode, 1000 transaction size ep_commit_time_total: 156 ep_flush_duration_total: 208 3) WAL mode, 100000 transaction size ep_commit_time_total: 108 ep_flush_duration_total: 180 4) WAL mode, 250000 transaction size ep_commit_time_total: 95 ep_flush_duration_total: 194 "ep_commit_time_total" is the cumulative time in seconds spent by commit operations, and "ep_flush_duration_total" is the cumulative wall time in seconds spent by the flusher. "ep_commit_time_total" is actually included in "ep_flush_duration_total". As you can see, WAL write performance was improved a little bit by increasing the transaction size, but still worse than TRUNCATE mode. I think there are three main reasons for this: 1) Transaction size in WAL was decreased to 1000, which means that there are much more commit operations than TRUNCATE mode with 250K transaction size. The main reason we decrease the transaction size in WAL is that if we increase the transaction size, the WAL file will getting bigger and consequently the read performance will be dropped. 2) Checkpoint overhead with 1000 transaction size in WAL is still bigger than we expected. Note that if we increase the transaction size, we will have fewer commits, but each checkpoint overhead will be increased. 3) TRUNCATE mode does not require the deletion of the rollback journal file, which incurs less disk I/O overhead than DELETE and WAL modes. When a commit is executed, TRUNCATE mode simply truncates the rollback journal file to zero-length instead of deleting it. However, the main benefit of using WAL is to interleave read operations with writes operations. This means that WAL can provide the better read and write performance than the TRUNCATE mode if there are mixes of background fetch and persistence tasks, which is more realistic client use cases.

Chiyoung Seo added a comment - 05/Jan/11 4:02 PM Matt, Keith, and I discussed the following three solutions to this issue today, and Matt will communicate with Zynga to decide the final solution: 1) Switch back to the TRUNCATE mode. This won't provide interleaving DB read operations with write operations. 2) Having a separate disk device for the WAL file. This will increase both read and write performance in the WAL mode as having separate disk devices for the WAL file and the original database file will reduce the disk IO contention and overhead. 3) Increase the transaction size in the WAL. This will improve the write performance a little bit, but degrade the read performance as the WAL file will be getting bigger. I think (1) or (2) will be a more feasible approach.  

Chiyoung Seo added a comment - 22/Jan/11 2:39 PM If the client has much higher write operation rate than the read rate and wants persistence performance, it is recommended to use Truncate mode at this time.