stoically
commented
4 years ago It seems that the queries conditionally called based on the config options before_limit and after_limit are not optimized yet. Calling the following code
let mut config = Config::new();
let passphrase = "DEFAULT_PASSPHRASE".to_owned();
config = config.set_passphrase(passphrase);
let searcher = database.get_searcher();
let mut search_config = SearchConfig::new();
search_config.for_room("<snip>".into());
search_config.limit(10);
search_config.order_by_recency(true);
let search_batch = searcher.search(":D", &search_config).unwrap();
dbg!(search_batch.results);results in
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
90,63 0,772822 8683 89 13 futex
3,14 0,026788 8929 3 wait4
1,36 0,011626 3 3080 write
1,26 0,010752 2 3626 537 statx
0,84 0,007204 3 2274 719 openat
0,73 0,006187 2 2283 3 read
0,40 0,003422 2 1581 close
0,39 0,003360 6 510 mmap
0,26 0,002212 8 275 clone
0,22 0,001871 6 307 mprotect
0,20 0,001682 4 379 munmap
0,10 0,000853 3 216 ioctl
0,09 0,000777 2 336 getdents64
0,07 0,000630 2 264 264 mkdir
0,05 0,000406 135 3 execve
0,04 0,000382 2 156 brk
0,04 0,000375 1 242 fstat
0,02 0,000183 3 55 munlock
0,02 0,000174 1 92 pread64
0,02 0,000153 1 116 69 stat
0,02 0,000141 1 116 fcntl
0,01 0,000094 31 3 unlink
0,01 0,000088 3 24 rt_sigaction
0,01 0,000082 2 32 lstat
0,01 0,000078 4 18 getpid
0,00 0,000039 5 7 getcwd
0,00 0,000036 12 3 readlink
0,00 0,000025 3 7 sigaltstack
0,00 0,000022 0 24 prlimit64
0,00 0,000020 3 6 getrandom
0,00 0,000016 1 11 rt_sigprocmask
0,00 0,000016 0 58 mlock
0,00 0,000015 0 16 flock
0,00 0,000015 2 6 getuid
0,00 0,000015 1 10 geteuid
0,00 0,000015 2 7 statfs
0,00 0,000014 2 6 3 arch_prctl
0,00 0,000013 1 7 sched_getaffinity
0,00 0,000010 3 3 set_tid_address
0,00 0,000010 3 3 set_robust_list
0,00 0,000009 9 1 sysinfo
0,00 0,000008 4 2 uname
0,00 0,000008 2 4 getgid
0,00 0,000008 2 4 getegid
0,00 0,000007 0 15 7 access
0,00 0,000006 0 8 pipe2
0,00 0,000005 5 1 sched_yield
0,00 0,000004 0 35 mremap
0,00 0,000001 0 7 poll
0,00 0,000000 0 8 pwrite64
0,00 0,000000 0 1 socket
0,00 0,000000 0 1 socketpair
0,00 0,000000 0 4 ftruncate
0,00 0,000000 0 1 chdir
0,00 0,000000 0 2 epoll_ctl
0,00 0,000000 0 1 inotify_init
0,00 0,000000 0 1 epoll_create1
------ ----------- ----------- --------- --------- ----------------
100.00 0,852679 16350 1615 totaladding
search_config.after_limit(1);
search_config.before_limit(1);results in
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
78,09 3,366917 2 1626999 pread64
20,02 0,863369 11511 75 13 futex
0,66 0,028438 4 6575 write
0,29 0,012370 3 3626 537 statx
0,21 0,009089 4 2270 719 openat
0,18 0,007660 3 2264 read
0,11 0,004544 8 507 mmap
0,10 0,004277 2 1565 close
0,08 0,003322 12 272 clone
0,08 0,003291 8 376 munmap
0,06 0,002494 8 307 mprotect
0,03 0,001237 412 3 execve
0,02 0,001045 3 336 getdents64
0,02 0,000942 4 211 ioctl
0,02 0,000898 3 264 264 mkdir
0,01 0,000438 2 162 brk
0,01 0,000385 1 242 fstat
0,01 0,000295 2 116 69 stat
0,00 0,000198 3 55 munlock
0,00 0,000161 1 116 fcntl
0,00 0,000110 36 3 unlink
0,00 0,000084 1 58 mlock
0,00 0,000039 1 24 rt_sigaction
0,00 0,000034 1 32 lstat
0,00 0,000028 3 8 pwrite64
0,00 0,000024 1 16 flock
0,00 0,000015 5 3 readlink
0,00 0,000013 3 4 ftruncate
0,00 0,000012 1 7 sigaltstack
0,00 0,000010 10 1 chdir
0,00 0,000009 1 6 prlimit64
0,00 0,000008 1 5 rt_sigprocmask
0,00 0,000008 0 15 7 access
0,00 0,000007 1 7 statfs
0,00 0,000007 1 6 3 arch_prctl
0,00 0,000006 1 6 getrandom
0,00 0,000005 0 35 mremap
0,00 0,000005 0 7 sched_getaffinity
0,00 0,000004 1 3 set_tid_address
0,00 0,000004 1 3 set_robust_list
0,00 0,000002 0 18 getpid
0,00 0,000002 0 10 geteuid
0,00 0,000000 0 1 poll
0,00 0,000000 0 1 socket
0,00 0,000000 0 1 socketpair
0,00 0,000000 0 2 uname
0,00 0,000000 0 7 getcwd
0,00 0,000000 0 1 sysinfo
0,00 0,000000 0 6 getuid
0,00 0,000000 0 4 getgid
0,00 0,000000 0 4 getegid
0,00 0,000000 0 2 epoll_ctl
0,00 0,000000 0 1 inotify_init
0,00 0,000000 0 1 epoll_create1
0,00 0,000000 0 2 pipe2
------ ----------- ----------- --------- --------- ----------------
100.00 4,311806 1646651 1612 total
poljar
I have a 468MB sqlcipher DB for my events. It takes 170ms to
select * from events where event_id=?at the sqlcipher commandline, but it takes ~21s to perform a search for a fairly infrequent term in a modest sized room (returns ~30 hits from 4,600 events). Profiling on macOS via Instruments reveals that the search does 6 gigabytes of reads, taking 2s of disk IO, 1.6M pread() calls, and about 10s of AVX2 SHA512 - implying that we are working sqlite way too hard in whatever queries seshat is executing. We shouldn't need to read 6GB of data out of sqlite in order to return a single set of search results.adding indexes to the
eventstable on event_id and (event_id, room_id) didn't help.