VMware Tanzu In My Homelab: Excessive Disk I/O

I’ve been working on getting VMware Tanzu Kubernetes Grid deployed in my homelab for a bit now. While I have been able to successfully deploy the workspace management and supervisor cluster VMs, I have noticed very excessive disk I/O from those VMs.

I never would have noticed if I never looked at my NAS. After deploying the supervisor cluster VMs, the disk activity light for onboard SATA was on solid. The onboard SATA is used by the ZIL on my FreeNAS box. Activity lights for the spinning rust was not abnormal though.

So, I decided to start looking at some metrics, as I wanted to validate that it was indeed the supervisor cluster VMs.
NOTE: Another oddity I have found is that only the local [email protected] account has permissions to even view the supervisor cluster VMs. Is this normal or expected? My domain account has the Administrator role as well, but it is unable to view the VMs or even Workspace folder in the VMs & Templates view. It can see the vCLS VMs though.

Reviewing the virtual disk rate, we could see that there was a constant write rate of around 15-17MB/s on one of the VMs.

Now let’s look at the disk requests. We can see that this is pretty consistent at 4,000 IOPS.

Now we will look at one of the other VMs. This one is right around 10MB/s write and only 2,000 write requests per second. The third VM looks like the first, with 15-17MB/s and 4,000 IOPS.

Let’s take a look at the storage statistics. ADA8 is one of the ZIL SSDs. We see a constant write rate of roughly 38MB/s.

Now let’s take a look at the operations per second. I had just redeployed the supervisor cluster VMs, and you can clearly see that. About 4,000 ops/sec.

Just for fun, let’s look at the network interface statistics. Constant receive of roughly 350Mbps.

So I thought I would try and delve in to the individual VMs, and see if I could find the source.

First thing, we need to find the password for the root accounts on those VMs.
To do this, there’s a script you can run from the vCenter shell to output the password.
SSH to your vCenter shell, then run: /usr/lib/vmware-wcp/decryptK8Pwd.py

The output should look something like:

root@vcenter [ ~ ]# /usr/lib/vmware-wcp/decryptK8Pwd.py
 Read key from file
 Connected to PSQL
 Cluster: domain-c7:122bff4a-443d-4094-9035-be4e244286cd
 PWD: Ho+BBOatjFWS2s68flutg7xHYewt/Vy8BAvHNMUQcMhcqG3Havk4Lta4Sdf37wXA/fcmr4rVWBsc1l8LqSSfQrHqmsHfDpolgz8aI269Who6L43RNF283TvEpityLVWgYo+Ai2hOUKUdapzKgG5WPnBhSDyLttMUYAiVO9rrHSg=

Now that we have the password for the root account, we can SSH to the individual VMs.
SSH to one, log in with root and the password found from the script, and we can use the dstat utility:

/usr/bin/python3 /usr/bin/dstat

This will output disk and network activity. We could see, and validate, that sure enough we are writing to disk at an excessive rate, even htitting 20MB:

root@420631715fd538d484265a9a44e451cb [ ~ ]# /usr/bin/python3 /usr/bin/dstat
 You did not select any stats, using -cdngy by default.
 Color support is disabled as python-curses is not installed.
 /usr/bin/dstat:515: DeprecationWarning: Using or importing the ABCs from 'collections' instead of from 'collections.abc' is deprecated since Python 3.3,and in 3.9 it will stop working
   if isinstance(self.val[name], collections.Sequence) and not isinstance(self.val[name], six.string_types):
 --total-cpu-usage-- -dsk/total- -net/total- ---paging-- ---system--
 usr sys idl wai stl| read  writ| recv  send|  in   out | int   csw 
  14  10  41  35   0| 216k   16M|   0     0 |   0     0 |  17k   47k
   9   8  48  34   0|   0    14M|  37k   91k|   0     0 |  19k   44k
  12  13  41  34   0|   0    14M|  25k   57k|   0     0 |  15k   43k
   8   9  46  37   0|   0    15M|  25k   80k|   0     0 |  14k   47k
   9   9  46  36   0|   0    15M|  31k   69k|   0     0 |  16k   49k
   9   9  46  35   0|   0    16M|  35k   87k|   0     0 |  15k   46k
  19  12  38  31   0|   0    15M|  34k   72k|   0     0 |  16k   47k
  11  11  42  36   0|   0    15M|  35k   83k|   0     0 |  15k   47k
  29  18  25  28   0|   0    20M|  69k  222k|   0     0 |  19k   45k

We can ran the same utility on the other VMs that should show similar results from what we found in the VM statistics.

Let’s try another utility, to see if we might be able to find where all those writes are going! We can use pidstat for this one. I’m not going to output everything as a number of these processes are at 0 writes. Here are all the processes that are writing. We can absolutely see the culprit with the write rate and IO delay. fluent-bit with 15,408KB/s write and IO delay of 7,177,811.

root@420631715fd538d484265a9a44e451cb [ ~ ]# pidstat -d
 Linux 4.19.132-5.ph3-esx (420631715fd538d484265a9a44e451cb) 01/26/2021 x86_64(2 CPU)
 06:03:33 AM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
 06:03:33 AM     0         1      1.20      0.14      0.00      13  systemd
 06:03:33 AM     0        67      0.00     10.62      0.00   50003  jbd2/sda3-8
 06:03:33 AM     0        90      0.00     18.12      0.00    4155  systemd-journal
 06:03:33 AM     0       167      0.52      8.63      0.00       0  crond
 06:03:33 AM     0       173      1.88      3.91      0.00     232  vmtoolsd
 06:03:33 AM     0       285      0.34      6.91      0.10       0  sshd
 06:03:33 AM     0      5149      9.59    323.49      2.12      16  containerd
 06:03:33 AM     0      8320      7.62      0.00      0.00      36  registry
 06:03:33 AM     0      8469      0.01    155.83      0.00   18639  etcd
 06:03:33 AM     0     11639      0.00  15408.21      0.00 7177811  fluent-bit
 06:03:33 AM     0     12709      0.00      0.02      0.00       0  registry-agent
 06:03:33 AM     0     16287      0.06      5.28      0.00      25  python3
 06:03:33 AM     0     16363      0.00      0.06      0.00      57  python3
 06:03:33 AM     0     19825      0.31     11.29      0.00       0  kubelet
 06:03:33 AM     0     20703      0.01      0.67      0.00       1  kube-apiserver
 06:03:33 AM     0     23636      0.01      0.08      0.00       1  lwregd
 06:03:33 AM     0     23740      0.00      0.01      0.00       2  lsassd

Again, we can run the same utility one of the other VMs and find nearly identical results.

I spent a lot of time searching, and was not able to find any other reports of this behavior. Surely I can’t be the first one to experience this, I thought. So, let’s go make a thread on the VMware communities.


The one community user that responded stated they experienced the same issue, and found it was related to using a .local domain. Well, my homelab does have a .local domain.
Also referenced were a couple VMware KB articles related to DNS issues with .local domains.



But when reviewing both of those articles, the issue is related to the appliances not having a valid or usable DNS server configured. In both cases, the cause is described as not configuring DNS during deployment or having decommissioned the DNS servers.

Well, I did provide DNS server during deployments as well as search domain, and also validated that the supervisor cluster VMs could indeed resolve the hostname whether using short hostname or FQDN.

root@42068944986ef297cc64a8a2a234c0dd [ ~ ]# ping vcenter
PING vcenter.incendiary.local ( 56(84) bytes of data.
64 bytes from vcenter.incendiary.local ( icmp_seq=1 ttl=62 time=4.51 ms

So DNS didn’t appear to be the issue. Additionally, I did attempt to search the log file /var/log/vmware/fluentbit/consolidated.log and oddly it kept returning zero results for my vCenter.

root@42068944986ef297cc64a8a2a234c0dd [ ~ ]# cat /var/log/vmware/fluentbit/consolidated.log | grep vcenter.incendiary.local
root@42068944986ef297cc64a8a2a234c0dd [ ~ ]# cat /var/log/vmware/fluentbit/consolidated.log | grep vcenter
root@42068944986ef297cc64a8a2a234c0dd [ ~ ]# cat /var/log/vmware/fluentbit/consolidated.log | grep

Although I was able to find references to my vCenter when I viewed the log in a text editor.
But, all I could ever find were POST errors.

kube.var.log.containers.vsphere-csi-controller-7c646978db-dv8tn_vmware-system-csi_vsphere-syncer-117430760f80fea02e666c34a71f32c1f88887151b5e78639e9ff047a9e7b1b2.log: [1611621903.859503, {"log":"2021-01-26T00:45:03.859325213Z stderr F {\"level\":\"error\",\"time\":\"2021-01-26T00:45:03.859202328Z\",\"caller\":\"storagepool/intended_state.go:183\",\"msg\":\"Error fetching cluster properties for domain-c7. Err: Post \\\"https://vcenter.incendiary.local:443/sdk\\\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)\",\"TraceId\":\"2ed71762-b82f-4cfc-ad35-d82394e9ab6e\",\"stacktrace\":\"sigs.k8s.io/vsphere-csi-driver/pkg/syncer/storagepool.isRemoteVsan\\n\\t/build/mts/release/bora-17165480/cayman_vsphere_csi_driver/vsphere_csi_driver/src/pkg/syncer/storagepool/intended_state.go:183\\nsigs.k8s.io/vsphere-csi-driver/pkg/syncer/storagepool.newIntendedState\\n\\t/build/mts/release/bora-17165480/cayman_vsphere_csi_driver/vsphere_csi_driver/src/pkg/syncer/storagepool/intended...

Well, I then got a VMware staffer to respond; depping, runs yellow-bricks.com and CTO Office Cloud Platforms. Neat!

He agreed that this sounds extreme, raised it with some folks, then had engineering looking in to it!

Let me raise this with a few folks, that sounds very extreme indeed.

Agreed, engineering is looking into it.

Sure enough, on February 4 he updated that this is indeed a bug! Engineering was able to reproduce the issue and are now investigating. Though I still don’t know if it actually is related to a .local domain or something else. I have not yet seen a KB article related, and I’ve been trying to keep my eyes open for one.

Issue has been confirmed in our engineering environment as well, it is being investigated and hopefully fixed in a future release. If you run this in production I would recommend filing an SR for it and submitting all details, that way it can be attached to the engineering issue.

So, there is a bug that causes an excessive amount of disk I/O, specifically disk writes due to logging.

It seems you may be able to decrease the logging level, but I have no idea what the full impact would be. The other community user that responded did provide a way to decrease the logging level. The post is no longer there; I don’t know if the user removed it or a mod did. I received the post in an email notification though.

I can take no responsibility for this, and use at your own risk:

I solved the problem with these steps:
Change Log_Level for fluentbit from debug to info using:
kubectl edit configmap fluentbit-config -n vmware-system-logging
delete and recreate daemonset.apps/fluentbit in namespace vmware-system-logging
No more useless thousand of loglines per second.
It's down from 1500 IOPS to 50 IOPS for each VM Also CPU usage went down from ~1500 MHz to ~800 MHz
I would recommend opening a case with vmware before implementing this. I dont want to struggle with vmware support and just 'for my VMUG homelab and will just use this modification in my VMUG lab

If or when I see/find the KB article, I will post the link here.

Update 02/26/2021: Issue is only related to default logging level of fluent-bit. It’s doing debug logging instead of warning.

Still unsure of the KB, been keeping an eye open but have not yet seen or found it.

In a production environment, seems VMware support just suggests disabling fluent-bit logging, per a post by a user on my VMware community thread.

I got an answer back on my SR. It was a simple fix for us:
You can disable fluentbit logging by:

1. ssh into vcsa
2. editing /etc/vmware/wcp/wcpsvc.yaml on the vcsa
change logging_fluentbit_enabled: true => logging_fluentbit_enabled: false
3. service-control --restart wcp

Leave a Reply

Your email address will not be published. Required fields are marked *