Strange issue with l2arc

Status
Not open for further replies.
M

maxxoverclocker

Cadet
Joined
Feb 28, 2014
Messages
4
Hi all! I'm experiencing a strange issue with l2arc that began after the 9.10.2 update. I was wondering if anyone else had experienced the same. Basically after a few days of running, FreeNAS suddenly thinks that 700GiB of l2arc has magically transformed into 32EiB (Exabytes!!!) of l2arc. Then over the course of a few weeks, I begin experiencing ctl_datamove errors when clients using iscsi/nfs/smb protocols do deletes. This results in disk I/O timeouts for my VMs running on the vmfs datastores running off the NAS. I also begin noticing very sporadic and unpredictable performance from the pool while this is occuring, ranging from 200MiB/s -> 100KiB/s while doing large sequential writes. I found this thread: https://forums.freenas.org/index.ph...results-in-ctl_datamove-tag-on-aborted.40119/ which seems very similar to what I'm experiencing, however I'm not using any link aggregation protocols, nor is auto-negotiate set for my interface.

I'm using two 350GiB partitions on two separate disks for the l2arc.

Here is an example before a reboot (32EiB) note that it even says that 1,851/700GiB are consumed somehow:

[root@NAS] ~# zpool iostat -v volsata01
capacity operations bandwidth
pool alloc free read write read write
-------------------------------------- ----- ----- ----- ----- ----- -----
...
cache - - - - - -
gptid/58469bd6-9166-11e6-b0a2-0cc47abd1c65 926G 16.0E 21 10 1.57M 1.21M
gptid/5c02b182-9166-11e6-b0a2-0cc47abd1c65 925G 16.0E 20 10 1.57M 1.21M
-------------------------------------- ----- ----- ----- ----- ----- -----

and after a reboot (700GiB):

[root@NAS] ~# zpool iostat -v volsata01
capacity operations bandwidth
pool alloc free read write read write
-------------------------------------- ----- ----- ----- ----- ----- -----
...
cache - - - - - -
gptid/58469bd6-9166-11e6-b0a2-0cc47abd1c65 5.94M 350G 0 0 618 36.7K
gptid/5c02b182-9166-11e6-b0a2-0cc47abd1c65 5.29M 350G 0 0 618 37.2K
-------------------------------------- ----- ----- ----- ----- ----- -----

You can see this started happening right after I installed 9.10.2 on December 27th.
8tMd1lA.jpg


To give you a little background this is occurring on a pool consisting of two raidz2 groups of 6 drives each (12 disks total). This is my home NAS that just hosts media, crashplan backups, and esxi datastores for test/dev/experimentation. I'm not overly concerned with the data in the pool. My average block size is very large due to this being primarily a media server so the l2arc tables use very little memory. I'm not worried about the large size of l2arc. It uses less than 1G of memory to maintain the 700G of l2arc.

os: FreeNAS-9.10.2-U1 (86c7ef5)
cpu: Intel i3-6320 CPU @ 3.90GHz
memory: 64GiB of ECC
nic: Intel 10Gbase-SR
hba(s): LSI SAS2008

Here's what I get in the logs:


Feb 10 14:46:35 NAS Feb 10 14:46:35 NAS ctl_datamove: tag 0x1630b33 on (0:4:0) aborted
Feb 10 14:46:35 NAS Feb 10 14:46:35 NAS ctl_datamove: tag 0x1630b34 on (0:4:0) aborted
Feb 10 14:46:35 NAS Feb 10 14:46:35 NAS ctl_datamove: tag 0x4b054c on (1:4:0) aborted
Feb 10 14:46:35 NAS Feb 10 14:46:35 NAS ctl_datamove: tag 0x1630b32 on (0:4:0) aborted
Feb 10 14:46:35 NAS Feb 10 14:46:35 NAS ctl_datamove: tag 0x1630b31 on (0:4:0) aborted
Feb 10 14:46:35 NAS Feb 10 14:46:35 NAS ctl_datamove: tag 0x1630b30 on (0:4:0) aborted
Feb 10 14:46:23 NAS Feb 10 14:46:23 NAS (0:4:0/0): ctl_process_done: 102 seconds
Feb 10 14:46:23 NAS Feb 10 14:46:23 NAS (0:4:0/0): Tag: 0x16300f2, type 1
Feb 10 14:46:23 NAS Feb 10 14:46:23 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 09 08 f4 e8 00 00 08 00
Feb 10 14:46:23 NAS Feb 10 14:46:23 NAS (0:4:0/0): ctl_process_done: 100 seconds
Feb 10 14:46:23 NAS Feb 10 14:46:23 NAS (0:4:0/0): Tag: 0x1630aad, type 1
Feb 10 14:46:23 NAS Feb 10 14:46:23 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 10 1d 2e 90 00 00 18 00
Feb 10 14:46:23 NAS Feb 10 14:46:23 NAS (0:4:0/0): ctl_process_done: 102 seconds
Feb 10 14:46:23 NAS Feb 10 14:46:23 NAS (0:4:0/0): Tag: 0x16302ea, type 1
Feb 10 14:46:23 NAS Feb 10 14:46:23 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 16 81 ac 18 00 00 20 00
Feb 10 14:46:23 NAS Feb 10 14:46:23 NAS (0:4:0/0): ctl_process_done: 102 seconds
Feb 10 14:46:23 NAS Feb 10 14:46:23 NAS (0:4:0/0): Tag: 0x16300ec, type 1
Feb 10 14:46:23 NAS Feb 10 14:46:23 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 05 70 58 00 00 00 10 00
Feb 10 14:46:23 NAS Feb 10 14:46:23 NAS (1:4:0/0): ctl_process_done: 91 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (1:4:0/0): Tag: 0x4b0536, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (1:4:0/0): READ(10). CDB: 28 00 00 00 a9 b8 00 00 01 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (1:4:0/0): ctl_process_done: 92 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (1:4:0/0): Tag: 0x4b0533, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (1:4:0/0): COMPARE AND WRITE. CDB: 89 00 00 00 00 00 00 00 a9 b8 00 00 00 01 00 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 101 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x16303c2, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 18 33 31 40 00 00 68 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 100 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630aae, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): READ(10). CDB: 28 00 05 0f 62 00 00 01 00 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 97 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630abb, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 00 4c 9a 58 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 102 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x16300ed, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 05 70 99 30 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 102 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x16300f1, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 08 e3 7d 20 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 102 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x16300ee, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 06 ad 38 18 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 102 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x16300ef, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 08 e3 59 00 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 102 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x16300f5, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 0a ea 38 20 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 91 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ac1, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 01 c2 fe 4f 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 97 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630abf, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 0b bf 78 d8 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 97 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630abe, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 0b bf 78 b8 00 00 10 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 97 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630abd, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 00 a3 10 b8 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 97 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630abc, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 00 a3 10 18 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 97 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630aba, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 18 76 d9 68 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 97 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ab9, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 18 72 73 a0 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (1:4:0/0): ctl_process_done: 100 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (1:4:0/0): Tag: 0x4b0531, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (1:4:0/0): COMPARE AND WRITE. CDB: 89 00 00 00 00 00 00 00 a9 b8 00 00 00 01 00 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 96 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630aae on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ab8, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_datamove: 98 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 18 72 46 d8 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630abb on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 96 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_datamove: 96 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ab4, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630abb, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 18 0f e0 00 00 00 10 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630ad3 on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 96 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630ad1 on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ab7, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630acf on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630acd on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630aca on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630ac8 on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630ac6 on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630ac4 on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630ac1 on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630abf on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630abe on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_datamove: 96 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_datamove: 96 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630abf, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630abe, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 0b bf 78 d8 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 0b bf 78 b8 00 00 10 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630abd on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630abc on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_datamove: 96 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_datamove: 96 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630abd, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630abc, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 00 a3 10 b8 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 00 a3 10 18 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630aba on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 18 72 33 68 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630ab9 on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_datamove: 96 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_datamove: 96 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 00 4c 9a 58 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630aba, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ab9, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 18 76 d9 68 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 18 72 73 a0 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630ab8 on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630ab4 on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_datamove: 96 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_datamove: 95 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ab8, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ab4, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 18 72 46 d8 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x4b0531 on (1:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630ab7 on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 96 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_datamove: 96 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ab6, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ab7, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 18 72 31 30 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 18 72 33 68 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 95 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630ab6 on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ab5, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_datamove: 95 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 18 72 30 38 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ab6, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 96 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 18 72 31 30 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ab3, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630ab5 on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 00 00 e9 1d 00 00 01 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_datamove: 95 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 100 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ab5, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x16300f4, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 18 72 30 38 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 09 f2 28 28 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 18 0f e0 00 00 00 10 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630ab3 on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 96 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_datamove: 96 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ab2, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ab3, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 01 c2 ff 53 00 00 01 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 00 00 e9 1d 00 00 01 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 96 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630ab2 on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ab1, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_datamove: 96 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 08 fb 15 d8 00 00 10 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ab2, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 97 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 01 c2 ff 53 00 00 01 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ab0, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630ab1 on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): COMPARE AND WRITE. CDB: 89 00 00 00 00 00 00 00 ab f8 00 00 00 01 00 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_datamove: 96 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 97 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630ab1, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): Tag: 0x1630aaf, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 08 fb 15 d8 00 00 10 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 00 00 e9 b5 00 00 01 00
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS ctl_datamove: tag 0x1630ab0 on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:22 NAS (0:4:0/0): ctl_process_done: 100 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:21 NAS (0:4:0/0): ctl_datamove: 97 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:21 NAS (0:4:0/0): Tag: 0x16300f0, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:21 NAS (0:4:0/0): Tag: 0x1630ab0, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:21 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 08 e3 73 78 00 00 08 00
Feb 10 14:46:22 NAS Feb 10 14:46:21 NAS (0:4:0/0): COMPARE AND WRITE. CDB: 89 00 00 00 00 00 00 00 ab f8 00 00 00 01 00 00
Feb 10 14:46:22 NAS Feb 10 14:46:21 NAS (0:4:0/0): ctl_process_done: 100 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:21 NAS ctl_datamove: tag 0x1630aaf on (0:4:0) aborted
Feb 10 14:46:22 NAS Feb 10 14:46:21 NAS (0:4:0/0): Tag: 0x16300f6, type 1
Feb 10 14:46:22 NAS Feb 10 14:46:21 NAS (1:4:0/0): ctl_datamove: 98 seconds
Feb 10 14:46:22 NAS Feb 10 14:46:21 NAS (0:4:0/0): Tag: 0x1630aae, type 1
Feb 10 14:46:21 NAS Feb 10 14:46:21 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 0e bc 1b 50 00 00 08 00
Feb 10 14:46:21 NAS Feb 10 14:46:21 NAS (0:4:0/0): ctl_datamove: 97 seconds
Feb 10 14:46:21 NAS Feb 10 14:46:21 NAS (0:4:0/0): ctl_process_done: 100 seconds
Feb 10 14:46:21 NAS Feb 10 14:46:21 NAS (0:4:0/0): Tag: 0x1630aaf, type 1
Feb 10 14:46:21 NAS Feb 10 14:46:21 NAS (1:4:0/0): Tag: 0x4b0531, type 1
Feb 10 14:46:21 NAS Feb 10 14:46:21 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 00 00 e9 b5 00 00 01 00
Feb 10 14:46:21 NAS Feb 10 14:46:21 NAS (0:4:0/0): READ(10). CDB: 28 00 05 0f 62 00 00 01 00 00
Feb 10 14:46:21 NAS Feb 10 14:46:21 NAS (0:4:0/0): Tag: 0x16300f3, type 1
Feb 10 14:46:21 NAS Feb 10 14:46:21 NAS (1:4:0/0): COMPARE AND WRITE. CDB: 89 00 00 00 00 00 00 00 a9 b8 00 00 00 01 00 00
Feb 10 14:46:21 NAS Feb 10 14:46:21 NAS (0:4:0/0): WRITE(10). CDB: 2a 00 09 ac 90 b0 00 00 08 00


Any ideas? Seeing anything similar?
 
joeschmuck

joeschmuck

Old Man
Moderator
Joined
May 28, 2011
Messages
10,996
Two things:
1) Given your use case I'm not sure why you have an L2ARC. I would recommend you remove them.
2) Submit a Bug Report and state if you are going to continue using the L2ARC, then if you plan to keep it just roll back to your previous version for the time being just to be safe.
 
M

maxxoverclocker

Cadet
Joined
Feb 28, 2014
Messages
4
joeschmuck said:
Two things:
1) Given your use case I'm not sure why you have an L2ARC. I would recommend you remove them.
2) Submit a Bug Report and state if you are going to continue using the L2ARC, then if you plan to keep it just roll back to your previous version for the time being just to be safe.
Click to expand...

Thanks for the reply! I think my use case fits pretty well for l2arc. While media is the primary purpose, the VMs keep my l2arc hit rate between 40-60%. Which I'd say is pretty good. I'll submit a bug report soon.

Edit: https://bugs.freenas.org/issues/21098 created.
 
Last edited:
Ericloewe

Ericloewe

Server Wrangler
Moderator
Joined
Feb 15, 2014
Messages
20,194
maxxoverclocker said:
Thanks for the reply! I think my use case fits pretty well for l2arc. While media is the primary purpose, the VMs keep my l2arc hit rate between 40-60%. Which I'd say is pretty good. I'll submit a bug report soon.

Edit: https://bugs.freenas.org/issues/21098 created.
Click to expand...
Maybe, but it's still rather oversized. The 400GB range would make more sense. Try several sizes to see what gives the best performance (don't just look at the hit rate, L2ARC hit rate is naturally going to grow as you grow L2ARC because ARC is smaller because L2ARC metadata is stored in RAM).
 
M

maxxoverclocker

Cadet
Joined
Feb 28, 2014
Messages
4
Ericloewe said:
Maybe, but it's still rather oversized. The 400GB range would make more sense. Try several sizes to see what gives the best performance (don't just look at the hit rate, L2ARC hit rate is naturally going to grow as you grow L2ARC because ARC is smaller because L2ARC metadata is stored in RAM).
Click to expand...

So I went ahead and followed Alexander Motin's advice per his post on the bug report and disabled TRIM. 'vfs.zfs.trim.enabledoption = 0' However this got me thinking. I provisioned about 80% of my SSD's space, which may have been causing the TRIM issue. So I reduced my L2ARC to 400GB, but now, without TRIM enabled- won't I be causing the same problem? Blocks will only be freed up as they need to be written to instead of having TRIM pre-do all of this work?

I guess I'll find out, It'll take a day or two to fill up the L2ARC. Thanks for the help!
 
Status
Not open for further replies.

Important Announcement for the TrueNAS Community.

The TrueNAS Community has now been moved. This forum will now become READ-ONLY for historical purposes. Please feel free to join us on the new TrueNAS Community Forums.

Related topics on forums.truenas.com for thread: "Strange issue with l2arc"

Similar threads

O
  • Locked
Trouble replacing failed HDD in mirrored pool
Replies
4
Views
3K
paleoN
paleoN
A
SCSI sense: DATA PROTECT popping up randomly
Replies
5
Views
3K
VioletDragon
VioletDragon
Scampicfx
Resilvering in progress although zpool status shows every disk online
Replies
6
Views
4K
Scampicfx
Scampicfx
V
  • Locked
Please help, 7 Reported_Uncorrect Errors reported by smartctl !
Replies
5
Views
2K
Johnnie Black
Johnnie Black
D
Got another issue / r720XD / H310 in IT / FN 11.2
Replies
1
Views
2K
dmburgess
D
Top