Add stats to track number of open files and max open file limit of validator process #28945

HaoranYi · 2022-11-23T16:29:05Z

Problem

Recently, in kin-sim, validator crashes because of reaching the max number of open file limits.

It is useful to track the actual number of open files and max open files limits for the validator process to help debugging and trouble shooting.

Summary of Changes

add stats to track number of open file descriptors for validator process
log number of open files and max open file limits when account background service thread hit the limits and panic.

Fixes #

HaoranYi · 2022-11-28T23:22:27Z

It seems that procfs.fd_count didn't tracks files open by mmap.
It only tracks fopen(), i.e. rocksdb files and sockets.

sol@kin-validator-am6-1:~/src/solana$ ls -l /proc/30565/fd | wc -l

To get the number of mmaped file, use the following command.

sol@kin-validator-am6-1:~/src/solana$ wc -l /proc/30565/maps
282755 /proc/30565/maps

mvines · 2022-11-29T16:00:13Z

core/src/system_monitor_service.rs

+        let curr_num_open_fd = proc.fd_count().unwrap();
+        let curr_mmap_count = proc.maps().unwrap().len();


Have you measured how long this takes to execute with 2M open fds?

Yeah. It takes about 10.520629985s for 2M open fds. Maybe we can increase the report interval from 30s to 3 minutes?

may very well miss an event on a three minute interval

This all seems pretty blunt. Beyond append vecs, which seems like it would be covered by #28958, what other sources of unbounded fd/mmap growth exist and perhaps we can directly instrument those as well.

the dumb wc -l /proc/PID/maps is like 600ms (850ms if the file is copied aside first) on a box with 505k maps. should be linear to 2M, ~2.5s. i'm guessing it's all the parsing that's of no use to us which is accounting for the rest of that time?

$ time cat maps | sed -e 's:.*/$accounts\|accounts_index$/.*:\1:;t;c\ other' | sort | uniq -c 416730 accounts 82965 accounts_index 4980 other

sol@kin-validator-am6-1:~$ cat /proc/30565/maps| sed -e 's:.*/$accounts\|accounts_index$/.*:\1:;t;c\other' | sort | uniq -c 87885 accounts 191468 accounts_index 3399 other

thanks! I tried @t-nelson's command. Looks like #28958 tracks the append-vecs correctly. the other large chunk of mmaps are used for accounts_index, 191K. @jeffwashington probably, we should track the number of accounts_index mmap file too?

the dumb wc -l /proc/PID/maps is like 600ms (850ms if the file is copied aside first) on a box with 505k maps. should be linear to 2M, ~2.5s. i'm guessing it's all the parsing that's of no use to us which is accounting for the rest of that time?

yeah. it takes 1.51s to count 2M open mmaps.

thanks! I tried @t-nelson's command. Looks like #28958 tracks the append-vecs correctly. the other large chunk of mmaps are used for accounts_index, 191K. @jeffwashington probably, we should track the number of accounts_index mmap file too?

Here is the change to track accounts index mmap files.
#28984

validator/src/cli.rs

core/src/system_monitor_service.rs

bucket_map/src/bucket_storage.rs

t-nelson · 2022-11-29T17:10:01Z

bucket_map/Cargo.toml

@@ -14,6 +14,7 @@ edition = "2021"
 log = { version = "0.4.17" }
 memmap2 = "0.5.3"
 modular-bitfield = "0.11.2"
+procfs = "0.14.1"


does this crate handle the non-atomicity of multi-page reads in procfs?

core/src/system_monitor_service.rs

t-nelson · 2022-11-29T22:21:47Z

bucket_map/src/bucket_storage.rs

+    fn get_mmap_count() -> Option<usize> {
+        let pid = std::process::id();
+        let map_path = format!("/proc/{}/maps", pid);
+        let output = std::process::Command::new("wc")


we can avoid shelling out with something like https://doc.rust-lang.org/rust-by-example/std_misc/file/read_lines.html. just toss a .count() on after .lines()

we may want to copy the maps file to a temporary first, to avoid being bitten by non-atomic reads in procfs

It looks like readlines is slower than wc -l.

Time elapsed is: 3.10014196s

I guess /proc/pid/maps are in memory kernel data structure, which is faster to read than the file on disk.

I guess /proc/pid/maps are in memory kernel data structure, which is faster to read than the file on disk.

yeah it is. also means it can be updated from beneath you. which is where the non-atomicity issues come in that i keep crowing on about 😅

Yes. But since this is used to report a metric, a small difference, caused by not being atomic, would be fine, I think.

t-nelson · 2022-11-30T17:32:37Z

bucket_map/src/bucket_map.rs

+    std::fs::copy(map_path, copy_path.as_os_str()).unwrap();
+
+    let file = std::fs::File::open(copy_path).ok()?;
+    Some(std::io::BufReader::new(file).lines().count())


how's timing in comparison?

wc-l 1.5s wc-l-copy 1.7s readline 3.1s

looks like wc-l without copy is the fastest.

that's unexpected 🤔

did you try .lines() w/o copy?

yeah. .lines() w/o copy takes 2.87s
seems that wc is better optimized than rust lines() fn.

weird. i wonder if it's the utf-8 handling on the rust side. wc is probably dumb and assumes ascii 🤔

HaoranYi · 2022-12-05T14:10:13Z

@t-nelson @mvines
I made a few more changes and no longer used procfs crate as it slow and not available on mac os.
Can you give a quick review again? If there are no more questions, I would like to merge.
Thanks!

Co-authored-by: Michael Vines <[email protected]>

make open_fd stats only on linux platform

HaoranYi · 2022-12-06T19:31:31Z

I assume there are no more questions. Merge it now. Feel free to ping me if you have any more comments. Thanks!

t-nelson · 2022-12-06T20:46:03Z

sorry, i forgot to update here. i'm really not keen on shelling out. we're going to find that one stupid distro that doesn't have wc in coreutils. i was experimenting yesterday with ways to do it by hand. i got line counting of a pre-existing copy of /proc/PID/maps with ~450k maps down to ~0.045s average. for some reason reading straight from procfs seems to only support reading up to one page at a time, which adds a bunch of looping overhead. today i'm planning to dig through the wc source to see what kind of magic they're up to

mvines · 2022-12-06T20:52:14Z

err, yuck. 👎🏼 to adding that system wc dependency.
But generally I don't feel we need this PR entirely, so I'd be game to see a full revert and abandon the idea entirely. My previous comment that went unaddressed:

This all seems pretty blunt. Beyond append vecs, which seems like it would be covered by #28958, what other sources of unbounded fd/mmap growth exist and perhaps we can directly instrument those as well.

HaoranYi · 2022-12-06T21:23:48Z

err, yuck. 👎🏼 to adding that system wc dependency. But generally I don't feel we need this PR entirely, so I'd be game to see a full revert and abandon the idea entirely. My previous comment that went unaddressed:

This all seems pretty blunt. Beyond append vecs, which seems like it would be covered by #28958, what other sources of unbounded fd/mmap growth exist and perhaps we can directly instrument those as well.

The other big source of mmap is accounts index mmap files, which should be addressed in this pr
#28984

HaoranYi · 2022-12-06T21:39:23Z

ok. I will revert it.

t-nelson · 2022-12-06T21:54:23Z

The other big source of mmap is accounts index mmap files, which should be addressed in this pr

only map consumers besides accountsdb and accounts-index are anon mappings (which I don't think we make explicitly), the executable file and shared-objects

HaoranYi · 2022-12-06T22:00:31Z

Another big consumer of open fd is from rocksdb. Maybe there is a way to get the open fd from rocksdb?

t-nelson · 2022-12-06T22:18:23Z

Another big consumer of open fd is from rocksdb. Maybe there is a way to get the open fd from rocksdb?

are those the anon maps? i didn't see anything with a file path under the ledger dir

t-nelson · 2022-12-06T22:21:09Z

Another big consumer of open fd is from rocksdb. Maybe there is a way to get the open fd from rocksdb?

are those the anon maps? i didn't see anything with a file path under the ledger dir

ah ha!

https://github.com/facebook/rocksdb/blob/23af6786a997d3592e8a68f1a8d9e0699a6eae36/port/mmap.cc#L81-L82

so we can count anon maps out of procfs, but afaik there's no way to link them to their caller

HaoranYi · 2022-12-06T22:27:48Z

yes. count procfs lines will include them. But I doubt there is an API on rocksdb to report it.

t-nelson · 2022-12-06T22:51:11Z

random sampling

   3406 anon
 410375 /accounts/
  56116 /accounts_index/
     68 other

revert #28945

revert solana-labs#28945

HaoranYi force-pushed the lsof branch 3 times, most recently from 00f8c29 to e87ce35 Compare November 23, 2022 16:49

HaoranYi changed the title ~~Log number of open files and max open file limit when panic~~ Add stats to track number of open files and max open file limit of validator process Nov 23, 2022

HaoranYi force-pushed the lsof branch from b208a3a to b49d0d3 Compare November 23, 2022 20:37

HaoranYi requested a review from jeffwashington November 24, 2022 16:14

HaoranYi force-pushed the lsof branch from 7fc9765 to b681cf3 Compare November 29, 2022 00:59

mvines reviewed Nov 29, 2022

View reviewed changes

validator/src/cli.rs Outdated Show resolved Hide resolved

mvines reviewed Nov 29, 2022

View reviewed changes

core/src/system_monitor_service.rs Outdated Show resolved Hide resolved

mvines reviewed Nov 29, 2022

View reviewed changes

bucket_map/src/bucket_storage.rs Outdated Show resolved Hide resolved

mvines reviewed Nov 29, 2022

View reviewed changes

bucket_map/src/bucket_storage.rs Outdated Show resolved Hide resolved

t-nelson reviewed Nov 29, 2022

View reviewed changes

core/src/system_monitor_service.rs Outdated Show resolved Hide resolved

t-nelson reviewed Nov 29, 2022

View reviewed changes

t-nelson reviewed Nov 30, 2022

View reviewed changes

HaoranYi and others added 12 commits December 5, 2022 08:15

log number of open files when panic

cbafde8

add monitoring for open file descriptors stat

d01d116

add mmmap file count

6e8dd0e

fix

680218e

log mmap count

37ef340

Update validator/src/cli.rs

fb615a2

Co-authored-by: Michael Vines <[email protected]>

review feedbacks

b389a81

refactor SystemMonitorReportConfig

30d9c87

fix build

a4dfa36

increase fd report interval to 3 minutes

b294dae

fix

4cade8d

get mmap with wc-l

d4034df

HaoranYi added 8 commits December 5, 2022 08:17

clippy

e7d0697

share code

a8b5ffb

alternative impl

18acb4a

wc-l-copy

b01c509

don't use procfs as it is not supported on mac and windows.

5617c02

make open_fd stats only on linux platform

sort deps

a8274de

report number of open files

768ab6b

comments

46d4bec

HaoranYi force-pushed the lsof branch from b214a3e to 46d4bec Compare December 5, 2022 14:18

fix merge error

4f0fc12

HaoranYi force-pushed the lsof branch from 1b706fa to 4f0fc12 Compare December 5, 2022 17:35

HaoranYi merged commit bbd49ac into solana-labs:master Dec 6, 2022

HaoranYi deleted the lsof branch December 6, 2022 19:32

HaoranYi added a commit to HaoranYi/solana that referenced this pull request Dec 6, 2022

revert solana-labs#28945

751267f

HaoranYi mentioned this pull request Dec 6, 2022

Revert #28945 #29127

Merged

HaoranYi added a commit that referenced this pull request Dec 6, 2022

Revert #28945 (#29127)

33b1524

revert #28945

gnapoli23 pushed a commit to gnapoli23/solana that referenced this pull request Dec 16, 2022

Revert solana-labs#28945 (solana-labs#29127)

0a4a618

revert solana-labs#28945

nickfrosty pushed a commit to nickfrosty/solana that referenced this pull request Jan 4, 2023

Revert solana-labs#28945 (solana-labs#29127)

cd2c573

revert solana-labs#28945

		let curr_num_open_fd = proc.fd_count().unwrap();
		let curr_mmap_count = proc.maps().unwrap().len();

Add stats to track number of open files and max open file limit of validator process #28945

Add stats to track number of open files and max open file limit of validator process #28945

Conversation

HaoranYi commented Nov 23, 2022 • edited Loading

Problem

Summary of Changes

HaoranYi commented Nov 28, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

HaoranYi Nov 29, 2022 • edited Loading

Choose a reason for hiding this comment

HaoranYi Nov 29, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

HaoranYi Dec 1, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

HaoranYi commented Dec 5, 2022

HaoranYi commented Dec 6, 2022 • edited Loading

t-nelson commented Dec 6, 2022

mvines commented Dec 6, 2022

HaoranYi commented Dec 6, 2022 • edited Loading

HaoranYi commented Dec 6, 2022

t-nelson commented Dec 6, 2022

HaoranYi commented Dec 6, 2022

t-nelson commented Dec 6, 2022

t-nelson commented Dec 6, 2022

HaoranYi commented Dec 6, 2022

t-nelson commented Dec 6, 2022

HaoranYi commented Nov 23, 2022 •

edited

Loading

HaoranYi commented Nov 28, 2022 •

edited

Loading

HaoranYi Nov 29, 2022 •

edited

Loading

HaoranYi Nov 29, 2022 •

edited

Loading

HaoranYi Dec 1, 2022 •

edited

Loading

HaoranYi commented Dec 6, 2022 •

edited

Loading

HaoranYi commented Dec 6, 2022 •

edited

Loading