# HDD problems or something else?



## Dendros (Nov 13, 2020)

Hello.

I have a system with 4 mechanical HDDs and I have installed FreeBSD 12.1-p10 on one of them but it seems that FreeBSD runs a bit slow.

By "slow" I mean that, for example, when installing a package with pkg(8) the extraction of some - not all - packages is really slow (for example I have installed the Papirus icon theme and extracting it after downloading took about 10-15 minutes). And starting the GUI (Xfce 4.14) sometimes takes a bit longer than usual. Other than these hiccups, the system seems to run fine.

So, I'm thinking that there could be problems with the drive on which FreeBSD was installed so I booted into Debian and ran a long smartctl(8) test on FreeBSD's drive (`smartctl -t long /dev/sdc` -> that is the FreeBSD's disk). These are the results:


```
=== START OF READ SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED

General SMART Values:
Offline data collection status:  (0x80)    Offline data collection activity
                    was never started.
                    Auto Offline Data Collection: Enabled.
Self-test execution status:      (   0)    The previous self-test routine completed
                    without error or no self-test has ever 
                    been run.
Total time to complete Offline 
data collection:         ( 7313) seconds.
Offline data collection
capabilities:              (0x5b) SMART execute Offline immediate.
                    Auto Offline data collection on/off support.
                    Suspend Offline collection upon new
                    command.
                    Offline surface scan supported.
                    Self-test supported.
                    No Conveyance Self-test supported.
                    Selective Self-test supported.
SMART capabilities:            (0x0003)    Saves SMART data before entering
                    power-saving mode.
                    Supports SMART auto save timer.
Error logging capability:        (0x01)    Error logging supported.
                    General Purpose Logging supported.
Short self-test routine 
recommended polling time:      (   1) minutes.
Extended self-test routine
recommended polling time:      ( 122) minutes.
SCT capabilities:            (0x003d)    SCT Status supported.
                    SCT Error Recovery Control supported.
                    SCT Feature Control supported.
                    SCT Data Table supported.

SMART Attributes Data Structure revision number: 16
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x000b   100   100   016    Pre-fail  Always       -       0
  2 Throughput_Performance  0x0005   142   142   054    Pre-fail  Offline      -       69
  3 Spin_Up_Time            0x0007   115   115   024    Pre-fail  Always       -       197 (Average 201)
  4 Start_Stop_Count        0x0012   100   100   000    Old_age   Always       -       849
  5 Reallocated_Sector_Ct   0x0033   100   100   005    Pre-fail  Always       -       0
  7 Seek_Error_Rate         0x000b   100   100   067    Pre-fail  Always       -       0
  8 Seek_Time_Performance   0x0005   115   115   020    Pre-fail  Offline      -       34
  9 Power_On_Hours          0x0012   098   098   000    Old_age   Always       -       16352
 10 Spin_Retry_Count        0x0013   100   100   060    Pre-fail  Always       -       0
 12 Power_Cycle_Count       0x0032   100   100   000    Old_age   Always       -       848
192 Power-Off_Retract_Count 0x0032   100   100   000    Old_age   Always       -       853
193 Load_Cycle_Count        0x0012   100   100   000    Old_age   Always       -       853
194 Temperature_Celsius     0x0002   187   187   000    Old_age   Always       -       32 (Min/Max 15/39)
196 Reallocated_Event_Count 0x0032   100   100   000    Old_age   Always       -       0
197 Current_Pending_Sector  0x0022   100   100   000    Old_age   Always       -       0
198 Offline_Uncorrectable   0x0008   100   100   000    Old_age   Offline      -       0
199 UDMA_CRC_Error_Count    0x000a   200   200   000    Old_age   Always       -       0

SMART Error Log Version: 1
No Errors Logged

SMART Self-test log structure revision number 1
Num  Test_Description    Status                  Remaining  LifeTime(hours)  LBA_of_first_error
# 1  Extended offline    Completed without error       00%     16352         -
# 2  Short offline       Completed without error       00%         1         -

SMART Selective self-test log data structure revision number 1
 SPAN  MIN_LBA  MAX_LBA  CURRENT_TEST_STATUS
    1        0        0  Not_testing
    2        0        0  Not_testing
    3        0        0  Not_testing
    4        0        0  Not_testing
    5        0        0  Not_testing
Selective self-test flags (0x0):
  After scanning selected spans, do NOT read-scan remainder of disk.
If Selective self-test is pending on power-up, resume after 0 minute delay.
```

I don't know how to interpret these, are they good or bad?


----------



## PMc (Nov 13, 2020)

Dendros said:


> By "slow" I mean that, for example, when installing a package with *pkg* the extraction of some - not all - packages is really slow (for example I have installed the Papirus icon theme and extracting it after downloading took about 10-15 minutes). And starting the GUI (Xfce 4.14) sometimes takes a bit longer than usual. Other than these hiccups, the system seems to run fine.


[/QUOTE]

Just look what the machine does during these 10 minutes. `top -HPS` will show if a CPU is loaded and by which process. `gstat -po` will show which disks are how much busy and how long a request does take. `systat -ifstat` shows what is going thru the network. /var/log/messages should get some logging in case of disk timeouts.

The smart data is unreadable when lacking formatting, but doesn't seem to show a flaw.


----------



## Dendros (Nov 13, 2020)

Sorry, I will repost the SMART data, perhaps now it will be more clear:


```
=== START OF READ SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED

General SMART Values:
Offline data collection status:  (0x80)    Offline data collection activity
                    was never started.
                    Auto Offline Data Collection: Enabled.
Self-test execution status:      (   0)    The previous self-test routine completed
                    without error or no self-test has ever
                    been run.
Total time to complete Offline
data collection:         ( 7313) seconds.
Offline data collection
capabilities:              (0x5b) SMART execute Offline immediate.
                    Auto Offline data collection on/off support.
                    Suspend Offline collection upon new
                    command.
                    Offline surface scan supported.
                    Self-test supported.
                    No Conveyance Self-test supported.
                    Selective Self-test supported.
SMART capabilities:            (0x0003)    Saves SMART data before entering
                    power-saving mode.
                    Supports SMART auto save timer.
Error logging capability:        (0x01)    Error logging supported.
                    General Purpose Logging supported.
Short self-test routine
recommended polling time:      (   1) minutes.
Extended self-test routine
recommended polling time:      ( 122) minutes.
SCT capabilities:            (0x003d)    SCT Status supported.
                    SCT Error Recovery Control supported.
                    SCT Feature Control supported.
                    SCT Data Table supported.

SMART Attributes Data Structure revision number: 16
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x000b   100   100   016    Pre-fail  Always       -       0
  2 Throughput_Performance  0x0005   142   142   054    Pre-fail  Offline      -       69
  3 Spin_Up_Time            0x0007   115   115   024    Pre-fail  Always       -       197 (Average 201)
  4 Start_Stop_Count        0x0012   100   100   000    Old_age   Always       -       849
  5 Reallocated_Sector_Ct   0x0033   100   100   005    Pre-fail  Always       -       0
  7 Seek_Error_Rate         0x000b   100   100   067    Pre-fail  Always       -       0
  8 Seek_Time_Performance   0x0005   115   115   020    Pre-fail  Offline      -       34
  9 Power_On_Hours          0x0012   098   098   000    Old_age   Always       -       16352
 10 Spin_Retry_Count        0x0013   100   100   060    Pre-fail  Always       -       0
 12 Power_Cycle_Count       0x0032   100   100   000    Old_age   Always       -       848
192 Power-Off_Retract_Count 0x0032   100   100   000    Old_age   Always       -       853
193 Load_Cycle_Count        0x0012   100   100   000    Old_age   Always       -       853
194 Temperature_Celsius     0x0002   187   187   000    Old_age   Always       -       32 (Min/Max 15/39)
196 Reallocated_Event_Count 0x0032   100   100   000    Old_age   Always       -       0
197 Current_Pending_Sector  0x0022   100   100   000    Old_age   Always       -       0
198 Offline_Uncorrectable   0x0008   100   100   000    Old_age   Offline      -       0
199 UDMA_CRC_Error_Count    0x000a   200   200   000    Old_age   Always       -       0

SMART Error Log Version: 1
No Errors Logged

SMART Self-test log structure revision number 1
Num  Test_Description    Status                  Remaining  LifeTime(hours)  LBA_of_first_error
# 1  Extended offline    Completed without error       00%     16352         -
# 2  Short offline       Completed without error       00%         1         -

SMART Selective self-test log data structure revision number 1
 SPAN  MIN_LBA  MAX_LBA  CURRENT_TEST_STATUS
    1        0        0  Not_testing
    2        0        0  Not_testing
    3        0        0  Not_testing
    4        0        0  Not_testing
    5        0        0  Not_testing
Selective self-test flags (0x0):
  After scanning selected spans, do NOT read-scan remainder of disk.
If Selective self-test is pending on power-up, resume after 0 minute delay.
```

Additionally, I did run a small benchmark of the disk using diskinfo(1) in FreeBSD, the results are:


```
I/O command overhead:
    time to read 10MB block      0.126974 sec    =    0.006 msec/sector
    time to read 20480 sectors   0.997883 sec    =    0.049 msec/sector
    calculated command overhead            =    0.043 msec/sector

Seek times:
    Full stroke:      250 iter in   8.201265 sec =   32.805 msec
    Half stroke:      250 iter in   5.436290 sec =   21.745 msec
    Quarter stroke:      500 iter in   8.195377 sec =   16.391 msec
    Short forward:      400 iter in   2.752451 sec =    6.881 msec
    Short backward:      400 iter in   3.321364 sec =    8.303 msec
    Seq outer:     2048 iter in   0.153588 sec =    0.075 msec
    Seq inner:     2048 iter in   0.130773 sec =    0.064 msec

Transfer rates:
    outside:       102400 kbytes in   0.539472 sec =   189815 kbytes/sec
    middle:        102400 kbytes in   0.621512 sec =   164759 kbytes/sec
    inside:        102400 kbytes in   1.010047 sec =   101381 kbytes/sec
```

How are these results?
And I did another test, installed another icon theme using pkg(8) and the system became noticeably slower (mouse cursor speed was slowed, the GUI reacted slower to mouse clicks) during the extraction phase, gstat(8) showed that ada2 (FreeBSD drive) is at 100% and if I understood the report correctly, the write speed was oscillating between 1-5 MB/s.


----------



## Zvoni (Nov 13, 2020)

I remember having something similiar with an old Dell Optiplex3010.
In its BIOS the AHCI-Setting for the HDD's was disabled!
Switching it on increased the speed by a factor of at least 10.

Have you looked into your BIOS?


----------



## olli@ (Nov 13, 2020)

It might be helpful to see the boot messages related to ada2: `grep ada2 /var/run/dmesg.boot`


----------



## PMc (Nov 13, 2020)

Dendros said:


> And I did another test, installed another icon theme using pkg(8) and the system became noticeably slower (mouse cursor speed was slowed, the GUI reacted slower to mouse clicks) during the extraction phase, gstat(8) showed that ada2 (FreeBSD drive) is at 100% and if I understood the report correctly, the write speed was oscillating between 1-5 MB/s.


That might be the normal behaviour. If that "icon theme" consists of thousands of files, the disk will have to do many thousands of seeks (each costing 3-12 ms), Then it certainly will show 100% busy, and if these files are small, it will indeed move only a few MB per second.
The cache is rather ineffective as these are writes.
TCQ/NCQ will not speed it up much, because it's a single thread and no way to parallelize it.
Then, as the OS is on the same disk, and the disk is saturated, all access will delay and the OS gets slower.

There may well be ways to improve this, but at first impression it is not really uncommon. (When people say, an SSD might be 100 times faster, that must come from something. And this here is exactly where it comes from.)

So, one can either live with that, or get one or (for safety) two SSD, or start optimizing. And optimizing can get an elaborated piece of work. As olli@ said, start with dmesg. Then check the disk settings: `camcontrol identify adaX`. Then the filesystem options, design and layout (make the seeks shorter). Etc.


----------



## Dendros (Nov 13, 2020)

Sorry for the delayed response, I was busy.

Zvoni, yes, I did look into BIOS and AHCI is active so this is not the cause.

olli@, here is the dmesg:


```
grep ada2 /var/run/dmesg.boot
ada2 at ahcich2 bus 0 scbus2 target 0 lun 0
ada2: <TOSHIBA DT01ACA100> ATA8-ACS SATA 3.x device
ada2: Serial Number
ada2: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 8192bytes)
ada2: Command Queueing enabled
ada2: 953869MB (1953525168 512 byte sectors)
Trying to mount root from ufs:/dev/ada2s1a [rw]...
```

PMc, perhaps you are right but I had FreeBSD installed on another system with a different mechanical HDD and I don't remember it being that slow, even when using *pkg* to install icon themes or lots of small files. That's why I'm a bit worried about my hard drive.
Anyway, here is the *camcontrol* report:


```
camcontrol identify ada2
pass2: <TOSHIBA DT01ACA100> ATA8-ACS SATA 3.x device
pass2: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 8192bytes)

protocol              ATA8-ACS SATA 3.x
device model          TOSHIBA DT01ACA100
firmware revision    
serial number        
WWN                  
additional product id
cylinders             16383
heads                 16
sectors/track         63
sector size           logical 512, physical 4096, offset 0
LBA supported         268435455 sectors
LBA48 supported       1953525168 sectors
PIO supported         PIO4
DMA supported         WDMA2 UDMA6
media RPM             7200
Zoned-Device Commands no

Feature                      Support  Enabled   Value           Vendor
read ahead                     yes    yes
write cache                    yes    yes
flush cache                    yes    yes
Native Command Queuing (NCQ)   yes        32 tags
NCQ Priority Information       yes
NCQ Non-Data Command           no
NCQ Streaming                  no
Receive & Send FPDMA Queued    no
NCQ Autosense                  no
SMART                          yes    yes
security                       yes    no
power management               yes    yes
microcode download             yes    yes
advanced power management      yes    no    0/0x00
automatic acoustic management  no    no
media status notification      no    no
power-up in Standby            yes    no
write-read-verify              no    no
unload                         no    no
general purpose logging        yes    yes
free-fall                      no    no
sense data reporting           no    no
extended power conditions      yes    yes
device statistics notification no    no
Data Set Management (DSM/TRIM) no
Trusted Computing              no
encrypts all user data         no
Sanitize                       no
Host Protected Area (HPA)      yes      no      1953525168/1953525167
HPA - Security                 yes      no
Accessible Max Address Config  no
```

My filesystem is UFS2, not ZFS, nothing special about the layout: a root slice and a swap one.


----------



## chrbr (Nov 13, 2020)

Dear Dendros,
I am by far no expert. But two things about the file system came into my mind.

1. https://www.freebsd.org/doc/en_US.ISO8859-1/books/handbook/configtuning-disk.html contains one section about soft updates. May be this helps if the option is not already applied.

2. It might help to mount the file system with the noatime option if this is not the case.

As a last resort it is never bad to try to swap the cables - just in case.


----------



## PMc (Nov 13, 2020)

From a quick scan thru the network, this Toshiba drive is supposed to be a Hitachi deskstar. 
I have a couple of these, they are weak on random seek - one of them runs in an array with a Seagate Barracuda, and I have often seen the Seagate being at ~40% utilization while the Deskstar is already at 100%.
OTOH, the Seagate consumes at least twice the power, and is delicate on conditions, quickly producing raw-read-errors and high-fly-writes, while the Hitachi are rather rugged, they have been occasionally run near 70 Celsius and are still working reliable for now almost 10 years.

Important to check: is your filesystem aligned to a 4k boundary?


----------



## ralphbsz (Nov 13, 2020)

The smartctl looks perfect, like a healthy disk. Not too old, not too many power cycles, no errors.
The performance numbers from diskinfo look reasonable. It's a very simple and silly way to measure performance, but the result is completely to be expected for a consumer desktop disk: 100...200 MByte/sec head throughput, 50-150 seeks per second depending on distance (the full stroke is unrealistic).

Question about your file system setup: The disk has 512 bytes logical block (sector) size, 4096 physical. Did you configure UFS for 4K sectors and align the partitions? Doing 512-byte updates on a disk that internally has to perform read-modify-write operations on 4K sectors will be slow.


----------



## Jose (Nov 13, 2020)

Anything in dmesg(8)? This is what a flaky SATA controller looks like on one of my boxes:

```
(ada0:ahcich1:0:0:0): WRITE_FPDMA_QUEUED. ACB: 61 00 40 91 c0 40 00 00 00 01 00 00
(ada0:ahcich1:0:0:0): CAM status: Uncorrectable parity/CRC error
(ada0:ahcich1:0:0:0): Retrying command, 3 more tries remain
```



ralphbsz said:


> The smartctl looks perfect, like a healthy disk. Not too old, not too many power cycles, no errors.


Hey Ralphbsz, any chance you would write a brief HOWTO on what to look for in SMART results?


----------



## Dendros (Nov 13, 2020)

I think that my filesystem is 4k aligned but I'm not sure as I did nothing special when installing the OS, just the normal procedure. Here is what *diskinfo* *-v ada2* shows about my disk:


```
ada2
    512             # sectorsize
    1000204886016    # mediasize in bytes (932G)
    1953525168      # mediasize in sectors
    4096            # stripesize
    0               # stripeoffset
    1938021         # Cylinders according to firmware.
    16              # Heads according to firmware.
    63              # Sectors according to firmware.
    TOSHIBA DT01ACA100    # Disk descr.
                # Disk ident.
    No              # TRIM/UNMAP support
    7200            # Rotation rate in RPM
    Not_Zoned       # Zone Mode
```

Is this 4k alignment?

Jose, I posted a dmesg about ada2 above. Does not show any error(s).


----------



## Jose (Nov 13, 2020)

Dendros said:


> Jose, I posted a dmesg about ada2 above. Does not show any error(s).


That's dmesg from boot. There may have been kernel messages about `ada2` after that. Run dmesg(8) in a terminal. That will display the latest kernel messages.


----------



## drhowarddrfine (Nov 13, 2020)

Dendros said:


> I booted into Debian and ran a long smartctl(8) test on FreeBSD's drive


In case you didn't know, `smartctl` is available on FreeBSD: sysutils/smartmontools


----------



## ralphbsz (Nov 13, 2020)

Dendros said:


> Is this 4k alignment?


No, diskinfo tells us about the hardware of the disk. It gives us one bit of information, which is that the physical block size is 4K, and that the offset of the first physical blocks in logical blocks is zero. The easier way to get this information by the way is with "camcontrol identify". But then, we need to make sure the software structures (the file systems, which are in turn on top of partitions) are aligned and use the correct block size. To verify that we have to start with gpart (to make sure the partition is not mis-aligned by a partial 4K block), and then at dumpfs for the file systems. I honestly don't even remember how to find the block size in the output of dumpfs for UFS, it is quite dense and cryptic, and I would have to spend a few minutes with the documentation. With ZFS it's easier for me (make sure ashift is at least 12), because I happen to remember that.


----------



## PMc (Nov 13, 2020)

Partition alignment:

```
# gpart show /dev/ada3
=>       40  234441568  ada3  GPT  (112G)
         40        472     1  freebsd-boot  (236K)
        512   10485760     2  freebsd-swap  (5.0G)
   10486272    2000000     3  freebsd-ufs  (977M)
   12486272    3200000     4  freebsd-ufs  (1.5G)
   15686272     600000     5  freebsd-ufs  (293M)
```
-> Leftmost column should be a multiple of 8.
UFS block size:

```
# dumpfs /dev/ada3p3 | grep fsize
fsize   4096    shift   12      mask    0xfffff000
```
 -> fsize should be 4096 or a multiple of that.


----------



## Dendros (Nov 13, 2020)

Jose: I checked dmesg messages after boot and there is nothing out of order, the messages about *ada2* are basically identical to boot messages.

ralphbsz: here are some results after running *gpart* on *ada2* and *dumpfs* (I have truncated dumpfs' output because its report is indeed quite long and I believe that the info from beginning of the report is the most relevant):


```
gpart show ada2
=>        63  1953525105  ada2  MBR  (932G)
          63           1        - free -  (512B)
          64  1953525104     1  freebsd  [active]  (932G)
```

and *dumpfs*:


```
magic    19540119 (UFS2)    time    Fri Nov 13 21:24:33 2020
superblock location    65536    id    [  ]
ncg    1518    size    243269632    blocks    235631026
bsize    32768    shift    15    mask    0xffff8000
fsize    4096    shift    12    mask    0xfffff000
frag    8    shift    3    fsbtodb    3
minfree    8%    optim    time    symlinklen 120
maxbsize 32768    maxbpg    4096    maxcontig 4    contigsumsize 4
nbfree    28313021    ndir    10129    nifree    121403912    nffree    5428
bpg    20035    fpg    160280    ipg    80256    unrefs    0
nindir    4096    inopb    128    maxfilesize    2252349704110079
sbsize    4096    cgsize    32768    csaddr    5056    cssize    24576
sblkno    24    cblkno    32    iblkno    40    dblkno    5056
cgrotor    189    fmod    0    ronly    0    clean    0
metaspace 6408    avgfpdir 64    avgfilesize 16384
flags    soft-updates+journal
check hashes    cylinder-groups
fsmnt    /
volname        swuid    0    providersize    243269632
```

Can you make any sense out of it? 

And I can say that the system really is abnormally slow, I installed flat remix icons from repo and it took over 20 mins for *pkg* to extract the package and during this Xfce became nearly unresponsive. Definitely not normal even for a mechanical HDD.


----------



## Jose (Nov 13, 2020)

Did you check /var/log/messages like Pmc suggested?


----------



## Dendros (Nov 13, 2020)

Yes, and there was nothing, I even searched for errors of any kind and all I found was something about mod_load vesa from console-kit, I don't think it's related.


----------



## ralphbsz (Nov 13, 2020)

I only have a moment right now, so here's half the answer: The gpart output looks good. It shows that the root file system begins at block 64. Now what I don't know whether that's a physical or logical block (to figure that out, we'd have to either read more documentation, or get the output from gpart list). But it doesn't matter, the number is divisible by 8, so even if it is logical blocks (512 bytes), the file system starts on a 4K boundary. I've seen people create partitions that are offset by one sector, and that absolutely kills performance (because then every 4K operation by the file system turns into a read-modify-write in the disk drive).

On the UFS output, your fragment size and block size look good, both are multiples of 4K. I think that means that all IO will be done in 4K blocks, and initial allocation in 32K units. What I don't know is how big inodes are; if they are still 512 bytes, this could get pretty slow when doing small file operation (creation in particular), but I don't remember how to adjust the inode size.

We can't use your "pkg" experiences as a good benchmark, since we have no idea what is really going on. Does installing those icons create 1 file, or 1000, or a million? Does it do other incredibly complex file system operations? Or is it CPU limited? I have no idea. To do performance optimization, you have to first measure where the bottleneck is.

Here is my suggestion: Using your favorite scripting language, write some simple file system benchmarks. All you need for this is shell: Create a example small file (say exactly 512 bytes), then create a temporary directory, and create 100 copies of the small file in that directory, for example with "cat example_file > temp_dir/file.${counter}", and then you use an expr loop to increment counter. How long does that take? How about 1M files? How about 1000 directories, each with 100 files? I just did that for fun on my system, and I can create ~300 files per second on either ZFS with a 7200RPM spinning disk, or UFS on an SSD.


----------



## Dendros (Nov 14, 2020)

ralphbsz said:


> I only have a moment right now, so here's half the answer: The gpart output looks good. It shows that the root file system begins at block 64. Now what I don't know whether that's a physical or logical block (to figure that out, we'd have to either read more documentation, or get the output from gpart list). But it doesn't matter, the number is divisible by 8, so even if it is logical blocks (512 bytes), the file system starts on a 4K boundary. I've seen people create partitions that are offset by one sector, and that absolutely kills performance (because then every 4K operation by the file system turns into a read-modify-write in the disk drive).
> 
> On the UFS output, your fragment size and block size look good, both are multiples of 4K. I think that means that all IO will be done in 4K blocks, and initial allocation in 32K units. What I don't know is how big inodes are; if they are still 512 bytes, this could get pretty slow when doing small file operation (creation in particular), but I don't remember how to adjust the inode size.
> 
> ...



I'm afraid I don't know much about shell scripting but I'm willing to give this a try, if you can give me an example code. 

My "*pkg* experience" on the current system is definitely not normal - I can say this because I have FreeBSD installed on another system with a spinning HDD that does not exhibit this issue. So clearly something is not OK.
Until now, I never encountered this kind of problem - that using *pkg* to install some programs can nearly hang the system. 
And this problem not limited to installing icon themes (although it's most visible in this case) but also other programs that seem to consist of many small files. For example, *lib boost* was a dependency of another big package and it took a long time for it to be extracted, much longer than usual. Another example: installing python as a dependency of a package took longer than expected and so on.


----------



## ralphbsz (Nov 14, 2020)

```
#!/bin/sh
tempdir=temp_create_files
mkdir $tempdir
dd if=/dev/random of=$tempdir/master.file bs=512 count=1

cycles=1000
counter=0
while [ $counter -lt $cycles ]
do
  cat $tempdir/master.file > $tempdir/file.$counter
  counter=$(($counter + 1))
done
```
Save that script (for example in measure_create_files), make it executable with chmod a+x measure_create_files. Then run it as follows: /usr/bin/time ./measure_create_files.

Here is what it does: It creates one file with random content (by reading 512 bytes from /dev/random), then creates 1000 files that are copies of this. The time command in front will tell you how long it ran. On my machine, it says "3.64 real 0.88 user 2.71 sys", meaning it took 3.6 seconds, or 3.6 milliseconds per file, or about 300 files per second. That's running on ZFS, with 7200 rpm nearline disks underneath. Note that nearly all of the wall clock time (3.6 seconds) was spent as CPU time (0.9 and 2.7 seconds), so this test is not disk limited, but CPU limited. I ran the same test on a UFS file system on top an SSD, and I get fundamentally the same answer: I'm CPU limited, not disk limited. I don't have a UFS file system that uses spinning disks at home. For fun, I ran the exact same script on a Mac (with an SSD), which was a little slower (250 files per second), and only 3/4 disk limited, on a cloud-hosted FreeBSD machine (much faster, but I don't know how it is virtualized and what the CPU speed there is), and a cloud-based Linux machine (even faster, again I have no idea what the underlying hardware is).


----------



## Dendros (Nov 14, 2020)

OK, saved your script as *test.sh* and ran it. Here is the output:


```
/usr/bin/time ./test.sh
1+0 records in
1+0 records out
512 bytes transferred in 0.000162 secs (3167161 bytes/sec)
        0.92 real         0.26 user         0.66 sys
```

How is it? And thanks for your help and patience.


----------



## ralphbsz (Nov 14, 2020)

OK, so you needed 0.92 seconds (wall clock time) to create 1000 files, or slightly less than 1ms per file. Of that, 100% was spent on CPU time (add 0.26 and 0.66 seconds), so the storage subsystem was completely amortized (probably due to parallelism). That's very fast, 3 times than my server (which runs at 1 GHz with a 32-bit CPU). That also means that your storage subsystem is completely not limited by the disk itself, but in this trivial test (of creating tiny files, and the inodes and directory entries for them) only by CPU power.

My conclusion: Your disk speed is irrelevant *TO THIS TEST*. We can now make a leap of faith, and generalize that to all small file operations. Which means that either (a) the performance of the pkg command is to be expected, or (b) there is another bottleneck that we don't know about.

Your next task: Using tools like top, iostat and vmstat, measure what parts of the system are busy when doing that pkg command again.


----------



## ralphbsz (Nov 15, 2020)

If I were interested in how long it takes to write one file *AND* get it flushed to disk, I would have done that. But here, we're trying to create a synthetic micro-benchmark, which somewhat resembles the OP's use case: creating a lot of small files from a program (in this case pkg), very likely without intervening sync. So this benchmark matches his use case.

For fun, I just ran the same thing with dd and oflag=(f)sync: It brings the performance on my ZFS (spinning rust) filesystem down to ~15ms/file (to be expected, the disks can take 8ms per revolution, and there are two disks), and about 4.6ms/file on ZFS with SSD (of which 3/4 is still the CPU time).


----------



## Dendros (Nov 15, 2020)

I did some more tests and during this I got an idea: what if I use the `time` command with `pkg`?
Result:


```
# time pkg install flat-remix-icon-themes
Updating FreeBSD repository catalogue...
FreeBSD repository is up to date.
All repositories are up to date.
Checking integrity... done (0 conflicting)
The following 1 package(s) will be affected (of 0 checked):

New packages to be INSTALLED:
    flat-remix-icon-themes: 20201017

Number of packages to be installed: 1

The process will require 290 MiB more space.

Proceed with this action? [y/N]: y
[1/1] Installing flat-remix-icon-themes-20201017...
[1/1] Extracting flat-remix-icon-themes-20201017: 100%
17.530u 36.655s 31:15.55 2.8%    2631+29066k 413+344842io 0pf+0w
```

As you can see, it took a long time to complete.

Here is `top`:


```
last pid: 89522;  load averages:  0.04,  0.11,  0.10    up 0+00:46:41  23:29:24
67 processes:  1 running, 66 sleeping
CPU:  1.0% user,  0.0% nice,  1.1% system,  0.2% interrupt, 97.6% idle
Mem: 1149M Active, 229M Inact, 1549M Wired, 1154M Buf, 13G Free
Swap: 3598M Total, 3598M Free

  PID USERNAME    THR PRI NICE   SIZE    RES STATE    C   TIME    WCPU COMMAND
18441 user         35  22    0   252M   108M select   3   0:40   5.44% Xorg
44837 user          5  20    0    84M    51M select   5   0:21   3.74% wrapper-
72156 root          1  20    0  1050M   893M biowr    7   0:31   2.65% pkg
31887 user         20  20    0   224M   105M select   0   0:12   1.69% xfwm4
53467 user          4  20    0   121M    56M select   6   0:11   0.87% xfce4-te
79511 root          1  20    0    11M  2868K nanslp   0   0:02   0.31% vmstat
67684 root          1  20    0    13M  3920K CPU7     7   0:01   0.06% top
84637 root          1  20    0    11M  2776K pause    7   0:00   0.01% iostat
61730 root          1  20    0    11M  2264K select   2   0:00   0.01% powerd
36101 user          4  20    0   111M    77M select   6   0:01   0.00% xfdeskto
34744 user          4  20    0    75M    43M select   3   0:01   0.00% xfce4-pa
19258 user         19  20    0   193M    79M select   6   0:01   0.00% xfce4-se
36864 user          4  20    0    75M    44M select   7   0:00   0.00% wrapper-
46092 user          4  20    0    72M    43M select   4   0:00   0.00% wrapper-
33926 user          4  20    0    60M    34M select   1   0:00   0.00% xfsettin
46854 user          4  20    0    71M    43M select   2   0:00   0.00% wrapper-
```

What does *biowr* state mean for `pkg`?

Here is `vmstat`:


```
vmstat -w 1
procs  memory       page                    disks     faults         cpu
r b w  avm   fre   flt  re  pi  po    fr   sr ad0 ad1   in    sy    cs us sy id
0 0 0 5.0G   12G     2   0   0   0   544  504   0   0  382  1979  2762  0  0 100
0 0 0 5.0G   12G     0   0   0   0   528  499   0   0  357  1541  2443  0  1 99
0 0 0 5.0G   12G     2   0   0   0   464  505   0   0  422  3097  3708  0  1 98
0 0 0 5.0G   12G     3   0   0   0    48  500   0   0  363  6580  5701  1  1 98
0 0 0 5.0G   12G   413   0   0   0  1017  497   0   0  549  5555  5084  1  1 98
0 0 0 5.0G   12G     2   0   0   0   681  501   0   0  212  4921  2353  0  0 99
0 0 0 5.0G   12G     0   0   0   0   384  502   0   0  310  2592  2358  0  0 100
0 0 0 5.0G   12G     2   0   0   0  1081  455   0   0  499  3562  4305  1  1 99
0 0 0 5.0G   12G     3   0   0   0   161  507   0   0  430  6637  5974  1  2 97
0 0 0 5.0G   12G     2   0   0   0   560  500   0   0  400  2479  3204  0  1 99
0 0 0 5.0G   12G     0   0   0   0   432  507   0   0  307  1239  2059  0  0 99
0 0 0 5.0G   12G     1   0   0   0   544  454   0   0  359  1267  2282  0  1 99
0 0 0 5.0G   12G     1   0   0   0    56  509   0   0  219  3817  3191  1  0 98
1 0 0 5.0G   12G     3   0   0   0   576  502   0   0  638  6906  7066  1  1 97
1 0 0 5.0G   12G     1   0   0   0   304  504   0   0  255  1606  2068  0  0 99
0 0 0 5.0G   12G     0   0   0   0   616  508   0   0  359  1340  2348  0  1 99
0 0 0 5.0G   12G     1   0   0   0     8  509   0   0   81   459   653  0  0 100
0 0 0 5.0G   12G     2   0   0   0   529  491   0   0  515  4880  5270  1  1 98
0 0 0 5.0G   12G     3   0   0   0   216  494   0   0  453  5768  5517  1  1 98
0 0 0 5.0G   12G     0   0   0   0   576  499   0   0  324  1150  2095  0  0 100
0 0 0 5.0G   12G     0   0   0   0   368  507   0   0  279   868  1720  0  0 99
```

And finally `iostat`:


```
iostat -w 1
       tty            ada0             ada1             ada2             cpu
tin  tout  KB/t tps  MB/s   KB/t tps  MB/s   KB/t tps  MB/s  us ni sy in id
   0   158  0.00   0  0.00   0.00   0  0.00  15.54  84  1.28   0  0  0  0 99
   3   461  0.00   0  0.00   0.00   0  0.00  18.35 249  4.46   0  0  0  0 99
  12   173  0.00   0  0.00   0.00   0  0.00  15.94 322  5.02   0  0  0  0 100
   4   162  0.00   0  0.00   0.00   0  0.00  15.76 203  3.12   1  0  0  0 99
   0   160  0.00   0  0.00   0.00   0  0.00  16.26 305  4.85   1  0  0  0 99
   0   160  0.00   0  0.00   0.00   0  0.00  16.43 279  4.48   0  0  1  0 99
   0   159  0.00   0  0.00   0.00   0  0.00  16.75 100  1.64   0  0  0  0 99
   0   157  0.00   0  0.00   0.00   0  0.00  16.10 330  5.18   1  0  1  0 99
   0   157  0.00   0  0.00   0.00   0  0.00  16.40 257  4.12   0  0  0  0 100
   0   162  0.00   0  0.00   0.00   0  0.00  12.97 292  3.69   1  0  0  0 99
   0   160  0.00   0  0.00   0.00   0  0.00  15.72 104  1.59   1  0  0  0 99
   0   160  0.00   0  0.00   0.00   0  0.00  15.52 372  5.63   0  0  0  0 99
   0   159  0.00   0  0.00   0.00   0  0.00  11.88  79  0.92   0  0  0  0 100
   0   157  0.00   0  0.00   0.00   0  0.00  14.52 343  4.87   0  0  0  0 99
   0   216  0.00   0  0.00   0.00   0  0.00  15.33 302  4.51   1  0  1  0 98
   0   162  0.00   0  0.00   0.00   0  0.00  13.60 209  2.78   2  0  1  0 97
   0   153  0.00   0  0.00   0.00   0  0.00  16.98 253  4.20   1  0  1  0 99
   0   163  0.00   0  0.00   0.00   0  0.00  14.71 304  4.37   1  0  0  0 99
   0   159  0.00   0  0.00   0.00   0  0.00  14.39 197  2.77   0  0  1  0 99
   0   161  0.00   0  0.00   0.00   0  0.00  15.34 245  3.67   1  0  1  0 99
   0   158  0.00   0  0.00   0.00   0  0.00  14.35 277  3.88   1  0  1  0 97
```

These reports are just samples (my FreeBSD disk is *ada2*). Do you see something amiss?


----------



## PMc (Nov 16, 2020)

Dendros said:


> I did some more tests and during this I got an idea: what if I use the `time` command with `pkg`?
> Result:
> 
> 
> ...



Oh well. Not really. That piece is 160'000 files.

I remember Usenet, there was a thing when there were really many files in a directory - I think it's called "indirect blocks", and it became ugly slow. This can also happen with not so very many files, but long filenames (as is the case here).
Then, I do not precisely know what pkg has to do, but probably it reads all the files back again to fill it's database. And the inode cache is probably exhausted with such a number.
Then, we have a mechanical disk with one single filesystem 1GB long, and it's a deskstar-alike that might take up to 18 ms to walk it.

So, lets suppose these indirect blocks make us need 4 seeks per file, and average 5 ms per seek (at least 2ms to settle in on a track, anyway), and we get 4 * 5 * 160'000 * 2 = 106 minutes.

As a matter of fact, most filesystems do not scale too well with 5- and 6-digit file numbers. There begins the realm where databases are better off. It does not hurt so much to access individual files from such a set, but moving them all as a bulk will become exponentially slower.



> What does *biowr* state mean for  pkg?



Something along the line of <waiting for a write command to complete>.



> ```
> 3   461  0.00   0  0.00   0.00   0  0.00  18.35 249  4.46   0  0  0  0 99
> 12   173  0.00   0  0.00   0.00   0  0.00  15.94 322  5.02   0  0  0  0 100
> 4   162  0.00   0  0.00   0.00   0  0.00  15.76 203  3.12   1  0  0  0 99
> ```



So there is about 250 transactions per seconds, which means some 4 ms seek time. And we're moving about 4 MB/sec. That is interesting: the whole set is supposed to be 290 MB, but 4*60*31 = 7440 MB. And that is probably the overhead from the indirect blocks read again and again.

There is some info about optimizing UFS for such use-cases in tuning(7). But since installation is usually a one-time action and not a use-case, that may or may not be worthwhile.


----------



## Dendros (Nov 16, 2020)

Well, I said that I have another system with FreeBSD installed on and which also has a spinning HDD, not a SSD. It's a HP SFF with a single 250 GB HDD and with FreeBSD 12.1-p10/amd64 as its sole OS.
Some info about its HDD, `camcontrol`:


```
# camcontrol identify ada0
pass0: <WDC WD2500AAKX> ATA8-ACS SATA 3.x device
pass0: 600.000MB/s transfers (SATA 3.x, UDMA5, PIO 8192bytes)

protocol              ATA8-ACS SATA 3.x
device model          WDC WD2500AAKX
firmware revision     
serial number         
WWN                   
additional product id
cylinders             16383
heads                 16
sectors/track         63
sector size           logical 512, physical 512, offset 0
LBA supported         268435455 sectors
LBA48 supported       488397168 sectors
PIO supported         PIO4
DMA supported         WDMA2 UDMA5
media RPM             7200
Zoned-Device Commands no

Feature                      Support  Enabled   Value           Vendor
read ahead                     yes    yes
write cache                    yes    yes
flush cache                    yes    yes
Native Command Queuing (NCQ)   yes        32 tags
NCQ Priority Information       yes
NCQ Non-Data Command           no
NCQ Streaming                  no
Receive & Send FPDMA Queued    no
NCQ Autosense                  no
SMART                          yes    yes
security                       yes    no
power management               yes    yes
microcode download             yes    yes
advanced power management      no    no
automatic acoustic management  no    no
media status notification      no    no
power-up in Standby            no    no
write-read-verify              no    no
unload                         no    no
general purpose logging        yes    yes
free-fall                      no    no
sense data reporting           no    no
extended power conditions      no    no
device statistics notification no    no
Data Set Management (DSM/TRIM) no
Trusted Computing              no
encrypts all user data         no
Sanitize                       no
Host Protected Area (HPA)      yes      no      488397168/488397167
HPA - Security                 yes      no
Accessible Max Address Config  no
```

`dumpfs`:


```
# dumpfs /dev/ada0s1 | grep fsize
fsize    4096    shift    12    mask    0xfffff000
```

`gpart`:


```
# gpart show ada0
=>       63  488397105  ada0  MBR  (233G)
         63          1        - free -  (512B)
         64  488397104     1  freebsd  [active]  (233G)
```

And `diskinfo`:


```
# diskinfo -v -c ada0
ada0
    512             # sectorsize
    250059350016    # mediasize in bytes (233G)
    488397168       # mediasize in sectors
    0               # stripesize
    0               # stripeoffset
    484521          # Cylinders according to firmware.
    16              # Heads according to firmware.
    63              # Sectors according to firmware.
    WDC WD2500AAKX    # Disk descr.
                # Disk ident.
    No              # TRIM/UNMAP support
    7200            # Rotation rate in RPM
    Not_Zoned       # Zone Mode

I/O command overhead:
    time to read 10MB block      0.081489 sec    =    0.004 msec/sector
    time to read 20480 sectors   2.168983 sec    =    0.106 msec/sector
    calculated command overhead            =    0.102 msec/sector
```

So, I did a test on this HP system, by installing the same *flat-remix-icon-themes* package and measuring the time taken to complete it. Here are the results:

`time`


```
# time pkg install flat-remix-icon-themes
Updating FreeBSD repository catalogue...
FreeBSD repository is up to date.
All repositories are up to date.
The following 1 package(s) will be affected (of 0 checked):

New packages to be INSTALLED:
    flat-remix-icon-themes: 20201017

Number of packages to be installed: 1

The process will require 290 MiB more space.
38 MiB to be downloaded.

Proceed with this action? [y/N]: y
[1/1] Fetching flat-remix-icon-themes-20201017.txz:   3%    1 MiB   1.5MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  11%    4 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  18%    7 MiB   2.9MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  25%   10 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  33%   13 MiB   2.9MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  40%   15 MiB   2.9MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  47%   18 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  55%   21 MiB   2.9MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  62%   24 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  70%   27 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  77%   30 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  85%   32 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  92%   35 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  99%   38 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz: 100%   38 MiB   2.9MB/s    00:14   
Checking integrity... done (0 conflicting)
[1/1] Installing flat-remix-icon-themes-20201017...
[1/1] Extracting flat-remix-icon-themes-20201017: 100%
18.914u 44.916s 3:08.39 33.8%    2664+28948k 287+346107io 1pf+0w
```

As you can see, installing this package was much faster on the HP system despite it having a smaller and presumably older HDD.

`iostat`


```
# iostat -w 1

      tty            ada0              cd0            pass0             cpu
 tin  tout  KB/t tps  MB/s   KB/t tps  MB/s   KB/t tps  MB/s  us ni sy in id
   0   134 15.78 2889 44.51   0.00   0  0.00   0.00   0  0.00   2  0  8  1 89
   0   235 15.09 3264 48.10   0.00   0  0.00   0.00   0  0.00   1  0  9  1 89
   0   133 14.65 3375 48.27   0.00   0  0.00   0.00   0  0.00   0  0  7  1 92
   0    80 15.27 3526 52.58   0.00   0  0.00   0.00   0  0.00   1  0  6  1 92
   0    79 11.48 3151 35.32   0.00   0  0.00   0.00   0  0.00   0  0  4  2 94
   0    75  5.86 2624 15.00   0.00   0  0.00   0.00   0  0.00   0  0  1  1 99
   0   143 16.43 2272 36.46   0.00   0  0.00   0.00   0  0.00   0  0  5  2 93
   0    79 17.15 3289 55.08   0.00   0  0.00   0.00   0  0.00   1  0  8  1 89
   0   134 17.16 3303 55.34   0.00   0  0.00   0.00   0  0.00   1  0 11  1 87
   0    79 17.15 3099 51.91   0.00   0  0.00   0.00   0  0.00   1  0 10  0 88
   0   134 19.35 2147 40.56   0.00   0  0.00   0.00   0  0.00   6  0  8  1 86
   0   189 18.27 2294 40.93   0.00   0  0.00   0.00   0  0.00   4  0  9  1 86
   0   134 17.89 2558 44.68   0.00   0  0.00   0.00   0  0.00   4  0  8  1 86
   0   134 17.25 3026 50.97   0.00   0  0.00   0.00   0  0.00   1  0  8  2 89
   0   134 14.85 2891 41.93   0.00   0  0.00   0.00   0  0.00   1  0  6  1 93
   0    79 14.95 3344 48.83   0.00   0  0.00   0.00   0  0.00   1  0  7  1 92
   0   134 16.07 3438 53.95   0.00   0  0.00   0.00   0  0.00   2  0  7  1 90
   0    79 14.71 3487 50.09   0.00   0  0.00   0.00   0  0.00   0  0  6  2 92
   0   134 15.15 3440 50.88   0.00   0  0.00   0.00   0  0.00   0  0  7  2 91
   0    79 15.33 3651 54.65   0.00   0  0.00   0.00   0  0.00   1  0  7  2 91
   0   134 15.23 3628 53.95   0.00   0  0.00   0.00   0  0.00   1  0  8  1 90
```

What do you think about these differences? I think it's clear that something is not OK with my current system, it should be faster or at least on par with the HP system regarding HDD speeds yet it's not.


----------



## ralphbsz (Nov 16, 2020)

I think your answer is here:
17.530u 36.655s 31:15.55 2.8%    2631+29066k 413+344842io 0pf+0w
That tells me that the pkg command took 31:15 minutes, or 1875 seconds. Of those, 54 seconds were spent using the CPU, or 2.8%. Which means lack of CPU power was completely not your bottleneck.

Next: Number of IOs. It did 413 read operations and 345K write operations. Let's ignore the reads (there are too few of them), the writes work out to about 180 write operations per second. Above you had measured that you can create small files in a little less than 1ms, or about 1000 per second. So 180 writes/second (assuming they are nearly all file creates) is in the ballpark, but still a factor of 5 slower than expected.

But we also know that pkg said it would write a total of 290 MiB. Divide that by the 180K write operations: average write size is 0.86KiB. That means our 1ms per file test (which ran at 1/2 KiB) was pretty close. Clearly, the file size difference can not explain the factor of 5. The total amount of IO won't save us: Modern disks run at 100-200 MByte/s, and writing 290 MiB total should take no more than 3s. 

Summarizing what we know so far: There is a factor of 5 between expected performance and measured performance is not explained by anything.

And then you add the measurement on the other machine, which is in a reasonable range (actually a little faster than expected). That indicates that something is serious wrong with your slow system. However, it is neither the disk nor the file system itself, as the small benchmark demonstrated that those can run at full speed. Honestly, I have no idea what it could be.


----------



## olli@ (Nov 16, 2020)

Dendros said:


> ```
> gpart show ada2
> =>        63  1953525105  ada2  MBR  (932G)
> 63           1        - free -  (512B)
> ...


That looks ok. But you’re using an “old-style” MBR partitioning scheme (not GPT) with a separate BSD partition table, which is not visible in the above output. So would you please show the output from `gpart show ada2s1`? It’s unlikely that it causes misalignment, but it doesn’t hurt to check.


----------



## PMc (Nov 16, 2020)

I tried to unpack that archive, and I also see ~3 minutes when writing it into pre-existing directories. So something seems to be wrong indeed, but from here I do not see what it might be.


----------



## olli@ (Nov 16, 2020)

BTW, just to make you drool    This is how long it takes to extract those 156.944 files to my NVMe SSD:

```
tar xf    1.76s user  8.42s system  99% cpu  10.174 total  6520kB RSS
```
Admittedly it’s twice as slow as my RAM disk (TMPFS) where it takes just 5 seconds. (This is an AMD Ryzen with 32 GB RAM.)

But seriously… I think that 3 minutes is a very good value for a modern HDD. But I wouldn’t be worried either if it took 10 minutes. Extracting a 6-digit number of small files is really a special case that exercises a lot of parts of the hardware, firmware, kernel (drivers, I/O scheduler, bus subsystem and so on) and userland software. Small details can make a huge difference.

For example, someone mentioned atime updates. These should be switched off for the /usr filesystem (mount option `noatime`), unless you need it for specific purposes. _Do not_ switch it off on the /var filesystem, or otherwise certain things will break, for example the detection of unread mail in /var/mail (this is just one of the reasons why you should partition your disk, instead of putting everything into a single filesystem).

When you use UFS (UFS2, to be exact), be sure to enable “soft updates” on the file system (`-U` option). I’m not sure if the FreeBSD installer does this by default nowadays, or if it still asks the user. Conversely, do _not_ enable journaling on the file system because it will increase the number of writes for meta data.

Another thing that might be worth a look is the sysctl `vfs.ufs.dirhash_maxmem`. Basically it specifies the maximum amount of “dirhash” memory, which is related to caching of directory entries. When extracting nearly 160.000 files, this will play a role. If you have plenty of RAM, you might consider increasing that sysctl. There are more tuning tips in the tuning(7) manual page.

By the way, I recently read in an article that a certain HDD manufacturer sold “7200 rpm class drives” that actually had only 5400 rpm. The rpm value has a significant impact on the random access speed of a drive. Also, some drives have “cheap” NCQ implementations in their firmware – basically just good enough to claim that NCQ is supported, but in practice they support only 2 tags (instead of the standard of 32 tags).


----------



## Dendros (Nov 16, 2020)

Again, thanks to all for your help and patience, I really appreciate this.

@oll@, here is `gpart show ada2s1`:


```
# gpart show ada2s1
=>         0  1953525104  ada2s1  BSD  (932G)
           0  1946157056       1  freebsd-ufs  (928G)
  1946157056     7368048       2  freebsd-swap  (3.5G)
```

Yes, I do use MBR and a simple partitioning scheme (root partition + swap partition) but I don't think it influences the results because I have the same partitioning scheme applied to both systems, the "slow" one and the HP SFF yet there is a significant difference between the regarding HDD speeds.

I found something strange: on the "slow" system I manually unpacked the .txz archive of the *flat-remix-icon-themes *package and it was quite fast, much faster than when it was unpacked by `pkg[B]`:[/B]


```
time tar xf flat-remix-icon-themes-20201017~816bbd6223.txz -C /home/user/Pictures/remix
tar: Removing leading '/' from member names
       28.33 real         4.62 user         7.56 sys
```

It seems as if the problem is exhibited only by `pkg` when it extracts a lot of small files. It's possible that pkg's performance is somehow influenced by the system's configuration?


----------



## CyberCr33p (Nov 16, 2020)

I had issues with random 4K read/writes with Toshiba disks. Check this thread:









						UFS - Toshiba disk low performance
					

I order a new dedicated server from a provider. The server has 2 Toshiba disks and the disk peformance is very slow. It's 3-4 times slower than other disks (for example Seagate).  I had the same problem in a production server (I notice it after I put it in production) and ask the datacenter to...




					forums.freebsd.org


----------



## richardtoohey2 (Nov 16, 2020)

It's not the SMR thing is it?  https://blocksandfiles.com/2020/04/29/toshiba-consumer-disk-drives-smr-list/

Sorry if a complete red herring!

This link says DT01 are CMR *not* SMR: https://blocksandfiles.com/2020/04/...ives-undocumented-shingle-magnetic-recording/


----------



## ralphbsz (Nov 17, 2020)

All these ideas about it being SMR, ultra-slow Toshiba drives, and 5400 rpm drives pretending to be 7200 have to deal with one ugly fact: The OP has run a benchmark of creating 1000 small files, and that benchmark runs really fast (better than 1ms per file). On the other hand, when running pkg (which from the file system end is probably doing nothing other than creating small files), performance drops to ~5.5 ms per file created. What is pkg doing the other 4.5 ms? Or is it doing the file creates in a fashion that causes the disk or file system to get really bad?

I've met experienced storage people who can always break a system (Hi Andy!). You tell them how your system works, they spend an hour coding up a little benchmark, and if you get lucky, your system runs really slow ... if you're unlucky, it crashes. It seems that pkg manages to exactly hit the achilles' heel of the OPs system. But we don't know why, we can't reproduce it on other systems, so this for now remains a mystery.


----------



## PMc (Nov 17, 2020)

CyberCr33p said:


> I had issues with random 4K read/writes with Toshiba disks. Check this thread:
> 
> 
> 
> ...


Now this is interesting, as this is supposed to be a server disk. From what we know, Toshiba has aquired the Fujitsu enterprise disk technology in 2009, and the IBM/HGST/WD 3.5" consumer technology (aka Deskstar) in 2012.
But what do they actually build? From the marketing babble, it is not an enterprise disk, it's an enterprize _capacity_ disk. Whatever that would mean.

But then, the pictures seem familiar. And what I believe is what I see:

ada0 = Western Digital Caviar Blue  (~2011)
ada2 = Seagate Barracuda 3.5          (?? 2017 ??)
ada5 = Hitachi HDS5C1010CLA382  (aka Deskstar, ~2012)


```
NAME            STATE     READ WRITE CKSUM
        bm              ONLINE       0     0     0
          raidz1-0      ONLINE       0     0     0
            ada0p5.eli  ONLINE       0     0     0
            ada2p1.eli  ONLINE       0     0     0
            ada5p1.eli  ONLINE       0     0     0

# ( cd /usr/ports ; tar cf - ) | tar xf -
L(q)  ops/s    r/s   kBps   ms/r    w/s   kBps   ms/w   %busy Name
    1    239     56    223    3.9    183   6870    0.5   26.7| ada0
    0    240     57    231    3.4    183   6858    0.5   24.6| ada2
    1    135     54    219    8.6     82   6082   12.4   57.6| ada5
```

These Deskstar can nicely run 24/7, and they are reliable - they just don't perform on transactional workload.


----------



## PMc (Nov 17, 2020)

ralphbsz said:


> All these ideas about it being SMR, ultra-slow Toshiba drives, and 5400 rpm drives pretending to be 7200 have to deal with one ugly fact: The OP has run a benchmark of creating 1000 small files, and that benchmark runs really fast (better than 1ms per file).


That is easy to deal with: these 1000 files will appear on the same track. No seek involved. UFS has a maxcontig parameter so large files will be distributed. AFAIK small files will not be distributed.


----------



## PMc (Nov 17, 2020)

Dendros said:


> I found something strange: on the "slow" system I manually unpacked the .txz archive of the *flat-remix-icon-themes *package and it was quite fast, much faster than when it was unpacked by `pkg[B]`:[/B]



Certainly pkg does a lot more than just unpack the archive - there are checksums logged and such things.

I tried similar things today (but didn't get a real clue from that). What I noticed is: if I just unpack such a big collection to some empty directury, then that runs rather fast (less than a minute).
But if I unpack it into a directory tree that does already exist, then that can take a couple of minutes. 

The explanation would be: if all directories and files are newly created, then they will all be created on the same disk tracks (which happen to be free). But when the directories do already exist, they can be anywhere on the disk (depending on how the filesystem was used before) and must be accessed where they are, and the seeks become longer. 
But it didn't appear like this could make the process reach half an hour over-all time.

If there were some spare disk space on Your system. one could create a fresh filesystem there and direct pkg to install there, and see how that behaves.


----------



## ralphbsz (Nov 17, 2020)

But: all the writes, in total, only amount to 290 MiB. I don't remember how much memory the OP's system has, but modern systems start at a handful of GB, so the total write footprint of the pkg command should be in RAM. That's why the write performance of the small benchmarks is so good: creating 1K or 100K files or directories can all be done without actually writing to the disk synchronously.

Could it be that pkg is using some fsync calls or something similar? What I'm trying to find out is: What is the bottleneck here? It's clearly not the CPU, nor should it be networking. The ~5.5ms per write indicates that seeks are being done for a large fraction of all IO operations, or we're waiting for platter rotation (either cache miss reads, or synchronous writes), and IO is the bottleneck. But that makes no sense, it should all be cacheable.


----------



## shkhln (Nov 17, 2020)

ralphbsz said:


> Could it be that pkg is using some fsync calls or something similar? What I'm trying to find out is: What is the bottleneck here? It's clearly not the CPU, nor should it be networking. The ~5.5ms per write indicates that seeks are being done for a large fraction of all IO operations, or we're waiting for platter rotation (either cache miss reads, or synchronous writes), and IO is the bottleneck. But that makes no sense, it should all be cacheable.


Pkg uses SQLite, so likely one transaction per package installed. That shouldn't create noticeable overhead, though.


----------



## Dendros (Nov 17, 2020)

My "slow" system's configuration: AMD FX 8350, 16 GB DDR3, RX 470 graphics and as I said 4 HDDs (they're independent, no RAID configuration whatsoever). And I configured `pkg` to use the -latest repo.

Someone suggested to use DTrace, it's possible to use it with `pkg` and could this help? I don't know how to use it but I'm willing to learn and give this a try too, as I'm quite baffled about this whole situation.


----------



## shkhln (Nov 17, 2020)

Dendros said:


> Someone suggested to use DTrace, it's possible to use it with `pkg` and could this help? I don't know how to use it but I'm willing to learn and give this a try too, as I'm quite baffled about this whole situation.


Start with pkg's own debug output: `env DEBUG_LEVEL=4 pkg install <the-slowest-to-install-package-you-can-think-of>`. The log unfortunately lacks timestamps, but it's still better than nothing.


----------



## PMc (Nov 17, 2020)

Dendros said:


> Someone suggested to use DTrace, it's possible to use it with `pkg` and could this help? I don't know how to use it but I'm willing to learn and give this a try too, as I'm quite baffled about this whole situation.


What about `truss -D 2>LOGFILE pkg install <whatver>` ?


----------



## shkhln (Nov 17, 2020)

anonymous9 said:


> I suggested DTrace because these are the types of problems that DTrace and eBPF (Linux) were developed to solve.  <appeal to authority removed>


That _only_ would help you if the file system performance is indeed the bottleneck. You did not do the necessary work to establish that. This problem could easily be caused by pkg running an enormous file list through some n^2 algorithm, for example.


----------



## shkhln (Nov 17, 2020)

PMc said:


> That piece is 160'000 files.


I can't believe this. Who the fuck approved this port?


----------



## PMc (Nov 17, 2020)

anonymous9 said:


> I suggested DTrace because these are the types of problems that DTrace and eBPF (Linux) were developed to solve.  Brendan Gregg who is a senior performance engineer at Netflix has created a number of DTrace scripts for FreeBSD.


I know, and You're welcome. But these things go quite deep into the muscles of the kernel.

In our case, it looks like pkg runs two cycles of operations. In the first it repeats creating temporary files::


```
0.000063517 openat(8,"usr/local/bin/.pkgtemp.raw2tiff.Ou9TA21KzOOh",O_WRONLY|O_CREAT|O_EXCL ...
0.000028340 ftruncate(10,0x4df8)                 = 0 (0x0)
0.000014510 fstat(10,{ mode=-rwxr-xr-x ,inode=6144,size=19960,blksize=19968 }) = 0 (0x0)
0.000038017 write(10,"\^?ELF\^B\^A\^A\t\0\0\0\0\0\0\0"...,19960) = 19960 (0x4df8)
0.000014902 close(10)                            = 0 (0x0)
0.000038922 utimensat(8,"usr/local/bin/.pkgtemp.raw2tiff.Ou9TA21KzOOh", ....
0.000031613 fchownat(8,"usr/local/bin/.pkgtemp.raw2tiff.Ou9TA21KzOOh",0,0, ...
0.000036272 fchmodat(8,"usr/local/bin/.pkgtemp.raw2tiff.Ou9TA21KzOOh",0100755,...
0.000013764 ioctl(1,TIOCGETA,0x7fffffffd1c0)     = 0 (0x0)
```

And later are repeats of this:


```
0.000024589 fstatat(8,"usr/local/bin/raw2tiff",{ mode=-rwxr-xr-x ...
0.000067371 unlinkat(8,"usr/local/bin/raw2tiff",0x0) = 0 (0x0)
0.000071079 renameat(8,"usr/local/bin/.pkgtemp.raw2tiff.Ou9TA21KzOOh",8,"usr/local/bin/raw2tiff"...
```

Now if these lines sum up to the major part of the run time, we don't need to look at anything else. And then we have the problematic syscall(s), and can start to analyse that with DTrace.


----------



## shkhln (Nov 17, 2020)

PMc said:


> In our case, it looks like pkg runs two cycles of operations. In the first it repeats creating temporary files::
> 
> 
> ```
> ...



Something like this?

```
DBG(3)[79822]> Scripts: executing
--- BEGIN ---
set -- papirus-icon-theme-20200602
/usr/local/bin/gtk-update-icon-cache  -q -f /usr/local/share/icons/Papirus 2>/dev/null || /usr/bin/true
/usr/local/bin/gtk-update-icon-cache  -q -f /usr/local/share/icons/Papirus-Dark 2>/dev/null || /usr/bin/true
/usr/local/bin/gtk-update-icon-cache  -q -f /usr/local/share/icons/Papirus-Light 2>/dev/null || /usr/bin/true
/usr/local/bin/gtk-update-icon-cache  -q -f /usr/local/share/icons/ePapirus 2>/dev/null || /usr/bin/true
Scripts: --- END ---
```
Yes, `gtk-update-icon-cache` performance should be tested.


----------



## shkhln (Nov 17, 2020)

shkhln said:


> Something like this?


Ok, I take this back. I didn't realize you selected the _tiff_ package for testing (instead of one of the icon theme packages OP mentions).


----------



## PMc (Nov 17, 2020)

shkhln said:


> Ok, I take this back. I didn't realize you selected the _tiff_ package for testing (instead of one of the icon theme packages OP mentions).


Never mind. I just grabbed the next best that was installed in that jail where I was logged in. I only wanted to see what it does.


----------



## olli@ (Nov 17, 2020)

Dendros said:


> ```
> # gpart show ada2s1
> =>         0  1953525104  ada2s1  BSD  (932G)
> 0  1946157056       1  freebsd-ufs  (928G)
> ...


That looks good. The alignment of your partitions should not cause any problems.

Also, the HDD in question is a PMR drive, so SMR is not an issue either.



> I found something strange: on the "slow" system I manually unpacked the .txz archive of the *flat-remix-icon-themes *package and it was quite fast, much faster than when it was unpacked by `pkg[B]`:[/B]


Yes, that’s normal, because pkg performs a lot of additional actions. Among other things, it calculates checksums and stores them in the SQLite database (separate transaction for every single file). I wouldn’t be surprised if this causes the difference that you’re seeing.


----------



## ralphbsz (Nov 17, 2020)

shkhln said:


> That _only_ would help you if the file system performance is indeed the bottleneck. You did not do the necessary work to establish that. This problem could easily be caused by pkg running an enormous file list through some n^2 algorithm, for example.


Nope, that's not it either: We know that CPU consumption is only 3% (or something like that, this is from memory) of the time spent. This is the basic problem here: we know that the slowdown (~20 minutes) is not caused by CPU consumption, nor can it be reasonably explained by file creation. So what is pkg doing? I have no idea. I like olli@'s suggestion that it might be SQlite: While the database that it is updating is really small, SQlite could be using some form of sync calls all the time. And a few hundred thousand sync calls (at 7200 rpm) will explain the 20 minutes. But: why does this happen on one machine and not on the other?

Could it be atime updates, causing the file system metadata buffers to be overflowing madly, and having to be spilled to disk? No, that makes no sense either, with McKusick soft updates those should end up as non-synchronous disk writes. Maybe soft updates aren't enabled (we might have discussed that already earlier in this thread, I forget)?


----------



## Dendros (Nov 17, 2020)

I decided to follow PMc's advice and use `truss`, since it seems more intuitive to use. The log file is too large (~269 MB), compressed it down to 17 MB, still cannot attach it.

But, out of frustration, I decided to do another test: took out the Toshiba HDD from the current system and installed it into the HP SFF system, just to see how FreeBSD and especially `pkg` would behave.
And guess what? Pkg behaved in the same way as it did on the original system, e.g it was slow to install a package that contains a lot of small files.

There is the possibility of the filesystem being the culprit but I think that we can eliminate this because I have installed FreeBSD in the same way on both systems (UFS, root+swap, no special configuration).

So, whatever the problem is, it's clearly related to the HDD itself. Yet it does not seem defective. Very puzzling. Should I replace it and be done with that?


----------



## ralphbsz (Nov 17, 2020)

Dendros said:


> The log file is too large (~269 MB), compressed it down to 17 MB, still cannot attach it.


Please don't attach it. To make any sense of it, we would have to do some data analysis, like group the system calls by category and destination, and measure average and variance of the length of the system calls, and then compare that to a good baseline. Sure, any performance tuning person is capable of doing that ... if they have an hour or a day. But I don't.



> So, whatever the problem is, it's clearly related to the HDD itself. Yet it does not seem defective. Very puzzling. Should I replace it and be done with that?


I think you're jumping to conclusions. You moved the physical disk (the piece of hardware that stores 512-byte blocks), and the whole file system (which has interestingly complex metadata, and internal configuration settings), and I think you probably even moved your whole OS with it (a huge amount of configuration information). Something in this giant package is what makes this operation slow, and we don't know what.

On the other hand, the "throw baby out with bathwater" technique might be helpful. And it also makes it so you and us won't waste any more time on the problem if it goes away, as it will destroy the evidence. But: I wouldn't throw the disk away and replace it yet (that costs money). Just wipe it clean (a format command probably wouldn't hurt), and then reinstall on it.


----------



## shkhln (Nov 18, 2020)

Dendros said:


> I decided to follow PMc's advice and use `truss`, since it seems more intuitive to use. The log file is too large (~269 MB), compressed it down to 17 MB, still cannot attach it.


Again, simply enable pkg's debug output and stare at it for, say, 10 minutes. Then abort the process and post the last ~100 lines here.

Also try `pkg --option RUN_SCRIPTS=false install -f <icon-theme-package>` (without debug logging) and `pkg --option INSTALL_AS_USER=true --option RUN_SCRIPTS=false --rootdir <whatever> install <icon-theme-package>` (without debug logging, without root) to rule out install script and package database issues.


----------



## shkhln (Nov 18, 2020)

ralphbsz said:


> Nope, that's not it either: We know that CPU consumption is only 3% (or something like that, this is from memory) of the time spent.


Fair enough.



ralphbsz said:


> I like olli@'s suggestion that it might be SQlite: While the database that it is updating is really small, SQlite could be using some form of sync calls all the time. And a few hundred thousand sync calls (at 7200 rpm) will explain the 20 minutes.


This is a good suggestion, although I'm not sure pkg is actually that paranoid with checksumming.



ralphbsz said:


> But: why does this happen on one machine and not on the other?


At least this seems to be completely deterministic.


----------



## PMc (Nov 18, 2020)

Dendros said:


> I decided to follow PMc's advice and use `truss`, since it seems more intuitive to use. The log file is too large (~269 MB), compressed it down to 17 MB, still cannot attach it.


Yes, and probably nobody here wants to read it either, because it is boringly repeating itself over 160'000 files.
But it is rather simple to read: in the first column is the time in seconds an operation did take, and the second column begins with the name of the operation - and all of the operations should have man pages telling what it does (which are more or less intellegible).
So, you can sort on the first column, you can group the operations and sum them up indivudally, etc.etc.etc., to see where the time is actually spent. And as you have two systems, you then can compare the times in detail. (For such an amount of lines this is best done with scripts, and a Unix provides ample command-line tools for just that purpose.)


Dendros said:


> But, out of frustration, I decided to do another test: took out the Toshiba HDD from the current system and installed it into the HP SFF system, just to see how FreeBSD and especially `pkg` would behave.
> And guess what? Pkg behaved in the same way as it did on the original system, e.g it was slow to install a package that contains a lot of small files.


Thank you. Not much surprize.


Dendros said:


> There is the possibility of the filesystem being the culprit but I think that we can eliminate this because I have installed FreeBSD in the same way on both systems (UFS, root+swap, no special configuration).
> 
> So, whatever the problem is, it's clearly related to the HDD itself. Yet it does not seem defective. Very puzzling. Should I replace it and be done with that?


That's up to you. It's a slow disk for such use-cases, and You didn't adhere to the documentation, which probably makes it worse.
`man tuning`


> It is not a good idea to make one large partition.  First, each partition
> has different operational characteristics and separating them allows the
> file system to tune itself to those characteristics.  For example, the
> root and /usr partitions are read-mostly, with very little writing, while
> ...


(Never mind - I set up my first in 1989, so I had quite some time to fiddle around for optimization.)


----------



## olli@ (Nov 18, 2020)

shkhln said:


> This is a good suggestion, although I'm not sure pkg is actually that paranoid with checksumming.


Well, yes, pkg calculates a checksum of _every single file_ and stores it in the pkg database (sqlite).
And sqlite itself can be configured to use several reliability modes. When full ACID-compliance is enabled, it syncs_ every single transaction_ to the drive. This is very slow, of course. I don’t know if pkg uses sqlite in this mode, though.

See the “Features” page on sqlite.org.

By the way: Be careful when looking for sqlite benchmarks: Often only the read performance is measured, which is quite fast, or a typical mixture (usually 90 % read + 10 % write). And benchmarks that measure the pure write performance often disable the durability (that’s the “D” in ACID), which means that the sync calls are skipped.


----------



## shkhln (Nov 18, 2020)

olli@ said:


> Well, yes, pkg calculates a checksum of _every single file_ and stores it in the pkg database (sqlite).


Why would it do that at _installation_ time? Checksums are present in a package manifest, as far as I can see.


----------



## olli@ (Nov 18, 2020)

shkhln said:


> Why would it do that at _installation_ time? Checksums are present in a package manifest, as far as I can see.


As far as I can see, the database does not store the manifest as a single object. Instead, the database schema has a table called “files” that contains one separate object per file. Every object contains three pieces of data: the path name of the file, the SHA256 checksum, and the database ID of the package to which this file belongs.

When you set the debug level to 4 (i.e. supply `-dddd` to the pkg command), it displays all of the SQL commands that it executes. This is very helpful to find out how the package database actually works (if you’re somewhat familiar with SQL).

For example, try `pkg -dddd which /usr/local/bin/python` (provided that Python is installed). Towards the end of the output there is a SELECT statement that performs a LEFT JOIN between the “packages” table and the “files” table in order to relate the package to the file name. In this example you can see how the database tables are structured.

[Edit] Of course you can also run `pkg -dddd install` with the package in question, in order to see the database transactions performed for those 160,000 files. I haven’t tried that myself, but I guess the output will be _huge_.


----------



## shkhln (Nov 18, 2020)

olli@ said:


> When you set the debug level to 4 (i.e. supply `-dddd` to the pkg command), it displays all of the SQL commands that it executes. This is very helpful to find out how the package database actually works (if you’re somewhat familiar with SQL).


I would not mention debug output 3 times in this thread (starting with https://forums.freebsd.org/threads/hdd-problems-or-something-else.77693/page-2#post-484620) if I weren't familiar with it.


----------



## olli@ (Nov 18, 2020)

shkhln said:


> I would not mention debug output 3 times in this thread (starting with https://forums.freebsd.org/threads/hdd-problems-or-something-else.77693/page-2#post-484620) if I weren't familiar with it.


My remark was not specifically addressed to you, but to all readers of this thread. I’m sorry if that was unclear.


----------



## Dendros (Nov 19, 2020)

I guess I have "solved" the problem by replacing the Toshiba drive with a Hitachi one that has 2 TB/64 MB cache. It runs much better, a `time` test shows this:


```
# time pkg install flat-remix-icon-themes
Updating FreeBSD repository catalogue...
FreeBSD repository is up to date.
All repositories are up to date.
The following 1 package(s) will be affected (of 0 checked):

New packages to be INSTALLED:
    flat-remix-icon-themes: 20201017

Number of packages to be installed: 1

The process will require 290 MiB more space.
38 MiB to be downloaded.

Proceed with this action? [y/N]: y
[1/1] Fetching flat-remix-icon-themes-20201017.txz:   5%    2 MiB   2.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  11%    4 MiB   2.6MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  18%    7 MiB   2.9MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  26%   10 MiB   2.9MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  33%   13 MiB   2.9MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  40%   16 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  48%   18 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  55%   21 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  63%   24 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  70%   27 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  78%   30 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  85%   32 MiB   2.9MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  92%   35 MiB   2.9MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz: 100%   38 MiB   3.1MB/s    00:13   
Checking integrity... done (0 conflicting)
[1/1] Installing flat-remix-icon-themes-20201017...
[1/1] Extracting flat-remix-icon-themes-20201017: 100%
19.041u 32.900s 5:10.07 16.7%    2584+28070k 174+346208io 72pf+0w
```

Much more reasonable.

Although the problem is not really solved since we have not found the cause of `pkg`'s behavior on the previous drive. The difference between the current drive and the previous one, besides the storage capacity, is the cache size - 64 MB vs 32 MB - so my very uneducated guess is that HDD's cache size somehow affected the performance of `pkg`'s operations.


----------



## shkhln (Nov 19, 2020)

Dendros said:


> we have not found the cause of `pkg`'s behavior


 "We" haven't tried to.


----------



## Dendros (Nov 20, 2020)

It was a figurative "we" but you're right. I still have the *truss* log file and the Toshiba drive which I can install into the HP system - I already said that I have tested it in the HP system and *pkg* behaved the same, it was slow - and "we" can give this another try if you're interested.  

Talking about problems, it seems I have another one. I said that in the current system I have 4 HDDs and one of those (the Toshiba drive) was replaced with a Hitachi drive with FreeBSD on it. 
Well, this Hitachi drive is identical to a drive from those 4 - another Hitachi which has a Windows installation on it. 
And when I say "identical", they really are - down to brand, model and firmware revision.

Here is the Hitachi drive with Windows (*ada2*):


```
# camcontrol identify ada2
pass2: <HUA723020ALA640> ATA8-ACS SATA 3.x device
pass2: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 8192bytes)

protocol              ATA8-ACS SATA 3.x
device model          HUA723020ALA640
firmware revision     
serial number         
additional product id
cylinders             16383
heads                 16
sectors/track         63
sector size           logical 512, physical 512, offset 0
LBA supported         268435455 sectors
LBA48 supported       3907029168 sectors
PIO supported         PIO4
DMA supported         WDMA2 UDMA6
media RPM             7200
Zoned-Device Commands no

Feature                      Support  Enabled   Value           Vendor
read ahead                     yes    yes
write cache                    yes    yes
flush cache                    yes    yes
Native Command Queuing (NCQ)   yes        32 tags
NCQ Priority Information       yes
NCQ Non-Data Command           no
NCQ Streaming                  no
Receive & Send FPDMA Queued    no
NCQ Autosense                  no
SMART                          yes    yes
security                       yes    no
power management               yes    yes
microcode download             yes    yes
advanced power management      yes    no    0/0x00
automatic acoustic management  no    no
media status notification      no    no
power-up in Standby            yes    no
write-read-verify              no    no
unload                         no    no
general purpose logging        yes    yes
free-fall                      no    no
sense data reporting           no    no
extended power conditions      yes    yes
device statistics notification no    no
Data Set Management (DSM/TRIM) no
Trusted Computing              no
encrypts all user data         no
Sanitize                       no
Host Protected Area (HPA)      yes      no      3907029168/3907029167
HPA - Security                 yes      no
Accessible Max Address Config  no
```

And here is the Hitachi drive with FreeBSD (*ada3*):


```
# camcontrol identify ada3
pass3: <HUA723020ALA640> ATA8-ACS SATA 2.x device
pass3: 300.000MB/s transfers (SATA 2.x, UDMA6, PIO 8192bytes)

protocol              ATA8-ACS SATA 2.x
device model          HUA723020ALA640
firmware revision     
serial number         
additional product id
cylinders             16383
heads                 16
sectors/track         63
sector size           logical 512, physical 512, offset 0
LBA supported         268435455 sectors
LBA48 supported       3907029168 sectors
PIO supported         PIO4
DMA supported         WDMA2 UDMA6
media RPM             7200
Zoned-Device Commands no

Feature                      Support  Enabled   Value           Vendor
read ahead                     yes    yes
write cache                    yes    yes
flush cache                    yes    yes
Native Command Queuing (NCQ)   yes        32 tags
NCQ Priority Information       yes
NCQ Non-Data Command           no
NCQ Streaming                  no
Receive & Send FPDMA Queued    no
NCQ Autosense                  no
SMART                          yes    yes
security                       yes    no
power management               yes    yes
microcode download             yes    yes
advanced power management      yes    no    0/0x00
automatic acoustic management  no    no
media status notification      no    no
power-up in Standby            yes    no
write-read-verify              no    no
unload                         no    no
general purpose logging        yes    yes
free-fall                      no    no
sense data reporting           no    no
extended power conditions      yes    yes
device statistics notification no    no
Data Set Management (DSM/TRIM) no
Trusted Computing              no
encrypts all user data         no
Sanitize                       no
Host Protected Area (HPA)      yes      no      3907029168/3907029167
HPA - Security                 yes      no
Accessible Max Address Config  no
```

Do you spot the problem? Despite of these drives being identical, down to the firmware revision, one of them (with Windows) is seen as being a SATA 3 (600 MB/s) device while the other (with FreeBSD on it) is seen as if it's a SATA 2 device (300 MB/s).
I have swapped physical SATA ports but no change, there is still this difference. I also changed the SATA cables, no dice.
My motherboard is a Gigabyte GA-970A-DS3P and according to its specs, all of its SATA ports are SATA 3, not a mix of SATA2/SATA3.

I really don't understand why is this difference.


----------



## ralphbsz (Nov 20, 2020)

First, the difference between the drives makes no sense.

But why are the firmware revision and manufacturer blank for you? And no serial number or WWN? This is the output of camcontrol identify on a few of my drives (just the first few lines):

```
pass0: <INTELSSDSA2SH064G1IB 43W7659 44E9163IBM 445C8860> ATA-7 SATA 2.x device
pass0: 300.000MB/s transfers (SATA 2.x, UDMA5, PIO 8192bytes)

protocol              ATA-7 SATA 2.x
device model          INTELSSDSA2SH064G1IB 43W7659 44E9163IBM
firmware revision     445C8860
serial number         CVEM001100R0064KGN
WWN                   5001517959194089
...

pass2: <Hitachi HDS5C3030ALA630 MEAOAA10> ATA8-ACS SATA 3.x device
pass2: 300.000MB/s transfers (SATA 2.x, UDMA5, PIO 8192bytes)

protocol              ATA8-ACS SATA 3.x
device model          Hitachi HDS5C3030ALA630
firmware revision     MEAOAA10
serial number         MJ0351YNG9RZ6A
WWN                   5000cca228c46d95
...

pass3: <HGST HMS5C4040BLE640 MPAOA5D0> ATA8-ACS SATA 3.x device
pass3: 300.000MB/s transfers (SATA 2.x, UDMA5, PIO 8192bytes)

protocol              ATA8-ACS SATA 3.x
device model          HGST HMS5C4040BLE640
firmware revision     MPAOA5D0
serial number         PL1331LAHEJ21H
WWN                   5000cca22ed43ca3
...

pass4: <ST2000LM007-1R8174 SBK2> ACS-3 ATA SATA 3.x device
pass4: 400.000MB/s transfers

protocol              ACS-3 ATA SATA 3.x
device model          ST2000LM007-1R8174
firmware revision     SBK2
serial number         ZDZ0BW5E
WWN                   5000c500a44a8bcf
...
```
The last one is on a USB3 interface, so it may have a strange transfer rate. So look: I have manufacturers, firmware revisions, serial numbers, and WWNs. You have none of those. Strange.


----------



## shkhln (Nov 20, 2020)

Dendros said:


> I already said that I have tested it in the HP system and *pkg* behaved the same,


Couldn't care less.



Dendros said:


> it was slow - and "we" can give this another try if you're interested.


Last time I checked, I had very specific questions.


----------



## PMc (Nov 20, 2020)

Dendros said:


> I have swapped physical SATA ports but no change, there is still this difference. I also changed the SATA cables, no dice.
> My motherboard is a Gigabyte GA-970A-DS3P and according to its specs, all of its SATA ports are SATA 3, not a mix of SATA2/SATA3.
> 
> I really don't understand why is this difference.


That is alright, both versions do exist, and may have the same model and even part number.
The actual spec might be written on the label.


----------



## Dendros (Nov 20, 2020)

shkhln: OK, I reinstalled FreeBSD on the HP system which now has the Toshiba drive in it and did some tests (your tests).
So, pkg with debugging enabled:


```
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/media-playlist-shuffle-symbolic-rtl.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/media-playlist-shuffle-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/microphone-sensitivity-high-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/microphone-sensitivity-low-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/microphone-sensitivity-medium-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/microphone-sensitivity-muted-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/microphone-sensitivity-none-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/mpi-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/my-caffeine-off-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/my-caffeine-on-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-acquiring-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-cellular-3g-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-cellular-4g-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-cellular-acquiring-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-cellular-cdma-1x-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-cellular-connected-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-cellular-disconnected-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-cellular-edge-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-cellular-error-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-cellular-gprs-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-cellular-hspa-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-cellular-no-route-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-cellular-offline-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-cellular-signal-excellent-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-cellular-signal-good-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-cellular-signal-none-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-cellular-signal-ok-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-cellular-signal-weak-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-cellular-umts-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-disconnected-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-error-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-idle-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-no-route-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-offline-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-receive-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-transmit-receive-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-transmit-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-vpn-acquiring-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-vpn-disconnected-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-vpn-error-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-vpn-no-route-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-vpn-offline-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-vpn-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-wired-acquiring-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-wired-disconnected-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-wired-error-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-wired-no-route-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-wired-offline-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-wired-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-wireless-acquiring-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-wireless-connected-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-wireless-disconnected-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-wireless-encrypted-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-wireless-error-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-wireless-hotspot-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-wireless-no-route-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-wireless-offline-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-wireless-signal-excellent-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-wireless-signal-good-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-wireless-signal-none-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-wireless-signal-ok-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/network-wireless-signal-weak-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/night-light-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/non-starred-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/notification-disabled-new-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/notification-disabled-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/notification-new-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/notification-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/numlock-disabled-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/numlock-enabled-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/nvidia-card-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/nvidia-ram-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/nvidia-temp-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/org.gnome.Shell.Extensions.GSConnect-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/org.perezdecastro.Revolt-status-blink-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/org.perezdecastro.Revolt-status-online-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/orientation-landscape-inverse-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/orientation-landscape-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/orientation-portrait-inverse-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/orientation-portrait-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/printer-error-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/printer-printing-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/printer-warning-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/process-completed-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/process-error-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/process-working-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/radio-checked-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/radio-mixed-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/radio-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/revolt-status-blink-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/revolt-status-online-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/rotation-allowed-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/rotation-locked-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/security-high-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/security-low-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/security-medium-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/semi-starred-symbolic-rtl.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/semi-starred-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/sensors-fan-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/sensors-temperature-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/sensors-voltage-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/software-update-available-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/software-update-urgent-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/starred-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/task-due-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/task-past-due-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/thunderbolt-acquiring-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/touchpad-disabled-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/touchpad-enabled-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/user-available-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/user-away-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/user-busy-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/user-idle-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/user-invisible-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/user-not-tracked-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/user-offline-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/user-status-pending-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/user-trash-full-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/view-private-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/view-wrapped-rtl-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/view-wrapped-symbolic-rtl.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/view-wrapped-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/weather-clear-night-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/weather-clear-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/weather-few-clouds-night-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/weather-few-clouds-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/weather-fog-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/weather-overcast-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/weather-severe-alert-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/weather-showers-scattered-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/weather-showers-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/weather-snow-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/weather-storm-symbolic.svg'
DBG(3)[15935]> Pkg: add new file '/usr/local/share/icons/Flat-Remix-Yellow/status/symbolic/weather-windy-symbolic.svg'
[1/1] Installing flat-remix-icon-themes-20201017...
DBG(4)[15935]> Pkgdb: running 'BEGIN IMMEDIATE TRANSACTION '
[1/1] Extracting flat-remix-icon-themes-20201017:  47%
```

I was staring at this process for about ~18 mins then killed it. The above lines are the last before aborting, I can describe the beginning: basically a connection was opened, the package was downloaded then lots of files were created as you can see above. Then when reaching the extraction phase, everything suddenly slowed to a crawl, the percent indicator barely changed, I stopped this process when it was at 47%.
I don't know if this report is useful but I can repeat the process if you want. 

No debugging, no scripts:


```
# time pkg --option RUN_SCRIPTS=false install -f flat-remix-icon-themes
Updating FreeBSD repository catalogue...
FreeBSD repository is up to date.
All repositories are up to date.
Checking integrity... done (0 conflicting)
The following 1 package(s) will be affected (of 0 checked):

New packages to be INSTALLED:
    flat-remix-icon-themes: 20201017

Number of packages to be installed: 1

The process will require 290 MiB more space.

Proceed with this action? [y/N]: y
[1/1] Installing flat-remix-icon-themes-20201017...
[1/1] Extracting flat-remix-icon-themes-20201017: 100%
24.289u 61.769s 33:37.76 4.2%    2631+29074k 151+345891io 0pf+0w
```

As user, no root, no debugging, no scripts:


```
$ time pkg --option INSTALL_AS_USER=true --option RUN_SCRIPTS=false --rootdir /home/user/Downloads/pkg install flat-remix-icon-themes
Updating FreeBSD repository catalogue...
Fetching meta.conf: 100%    163 B   0.2kB/s    00:01   
Fetching packagesite.txz: 100%    6 MiB   3.4MB/s    00:02   
Processing entries: 100%
FreeBSD repository update completed. 32732 packages processed.
All repositories are up to date.
The following 1 package(s) will be affected (of 0 checked):

New packages to be INSTALLED:
    flat-remix-icon-themes: 20201017

Number of packages to be installed: 1

The process will require 290 MiB more space.
38 MiB to be downloaded.

Proceed with this action? [y/N]: y
[1/1] Fetching flat-remix-icon-themes-20201017.txz:   1%  720 KiB 737.3kB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:   4%    2 MiB   1.2MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:   8%    3 MiB   1.6MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  13%    5 MiB   2.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  20%    8 MiB   2.5MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  27%   10 MiB   2.9MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  34%   13 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  42%   16 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  49%   19 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  57%   22 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  64%   25 MiB   2.9MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  71%   27 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  79%   30 MiB   2.9MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  86%   33 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  93%   35 MiB   2.6MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz:  97%   37 MiB   1.8MB/s    0[1/1] Fetching flat-remix-icon-themes-20201017.txz: 100%   38 MiB   2.5MB/s    00:16   
Checking integrity... done (0 conflicting)
[1/1] Installing flat-remix-icon-themes-20201017...
[1/1] Extracting flat-remix-icon-themes-20201017: 100%
     2042.88 real        34.11 user        59.18 sys
```

Not much of a difference in each case, the install time was about the same when extracting. So what's next?

PMc: perhaps you're right, I have to read the printed label on each and compare. Thanks for info.


----------



## shkhln (Nov 21, 2020)

Dendros said:


> Not much of a difference in each case, the install time was about the same when extracting. So what's next?



Try this script:

```
#!/usr/bin/env ruby
# encoding: UTF-8

system('mkfifo /tmp/pkg.events')

threads = []

threads << Thread.new do
  File.open('/tmp/pkg.events').each_line do |line|
    case line
      when /INFO_EXTRACT_BEGIN/
        system('pkill -SIGSTOP pkg')
        pid = `pgrep pkg`.lines.first.chomp.to_i # might not be the correct pid, YMMV
        threads << Thread.new do
          system("dtrace -n 'pid$target:pkg::entry { trace(timestamp / 1000000); }' -p #{pid}")
        end
        sleep 1
        system('pkill -SIGCONT pkg')
      when /INFO_EXTRACT_FINISHED/
        system('pkill dtrace')
        break
    end
  end
end

system('env EVENT_PIPE=/tmp/pkg.events pkg install -fy papirus-icon-theme')

threads.each do |t|
  t.join
end
```
No need to run it to completion. Just wait a couple of minutes. It should produce an output like this:

```
0  90258     pkg_emit_progress_tick:entry          60551705
  0  89754             pkg_emit_event:entry          60551705
  0  91216       pkg_plugins_hook_run:entry          60551705
  0  90051             event_callback:entry          60551705
  0  90022           progressbar_tick:entry          60551705
  0  90178           pkg_absolutepath:entry          60551705
  0  89774         do_extract_symlink:entry          60551705
  0  91107               pkg_get_file:entry          60551705
  0  89770            create_symlinks:entry          60551705
  0  89778        pkg_hidden_tempfile:entry          60551705
  0  91168                set_attrsat:entry          60551705
  0  91136                metalog_add:entry          60551705
```


----------



## Dendros (Nov 21, 2020)

shkhln: please explain a bit more on what this script does, especially if it needs to be run as root (is that the case?).

Thanks


----------



## Jose (Nov 22, 2020)

I'm not Shkhln, but I'll take a crack at it anyway

```
system('mkfifo /tmp/pkg.events')
```
Create a named pipe at /tmp/pkg.events

```
threads = []
```
Create an empty list of threads

```
threads << Thread.new do
  File.open('/tmp/pkg.events').each_line do |line|
```
Create a thread that reads from the named pipe one line at a time. We'll wait here if no lines are available.

```
case line
      when /INFO_EXTRACT_BEGIN/
```
If the line contains the text "INFO_EXTRACT_BEGIN"

```
system('pkill -SIGSTOP pkg')
```
Send the STOP signal to any process called "pkg" using pkill(1)

```
pid = `pgrep pkg`.lines.first.chomp.to_i # might not be the correct pid, YMMV
```
Grab the pid of any process called "pkg" using pgrep(1) and store it in a variable called "pid"

```
threads << Thread.new do
          system("dtrace -n 'pid$target:pkg::entry { trace(timestamp / 1000000); }' -p #{pid}")
        end
```
Start a new thread that creates a dtrace(1) probe for a provider called "pid$target" with module "pkg" and called "entry". This probe executes a single action. It takes the time in nanoseconds since boot and divides it by 1000000. The "-p" option means this trace will exit when the process with the associated pid exits, among other things. Consult the man page for more details.

```
sleep 1
        system('pkill -SIGCONT pkg')
```
Sleep for one second and then send the CONT signal to the pkg process

```
when /INFO_EXTRACT_FINISHED/
        system('pkill dtrace')
        break
```
Kill the dtrace probe if the next line read out of the pipe contains the text "INFO_EXTRACT_FINISHED". Exit the thread that reads the FIFO one line at a time. Both threads should exit at this point.

```
end
```
Skip to the next line if the current line  contains neither "INFO_EXTRACT_BEGIN" nor "INFO_EXTRACT_FINISHED". Wait for the next line if there are no lines to read in the pipe right now.

```
system('env EVENT_PIPE=/tmp/pkg.events pkg install -fy papirus-icon-theme')
```
Invoke pkg-install(8) and send JSON output to the named pipe /tmp/pkg.install. Force the (re)installation of x11-themes/papirus-icon-theme. Answer any prompts with "y".

```
threads.each do |t|
  t.join
end
```
Wait for all the threads to exit.

Yes, this requires root for at least the pkg-install step. The dtrace probe probably requires root, too. I don't know. I've never used dtrace.


----------



## Dendros (Nov 22, 2020)

Jose: thanks very much for your explanations. Then I should run this script and see if something will appear or not. I'm really curious on why does this problem with extracting occurs.


----------



## Dendros (Nov 22, 2020)

Ran this script for about 10 mins then stopped it. A sample:


```
3  80542       pkg_plugins_hook_run:entry           1686523
  3  79377             event_callback:entry           1686523
  3  79348           progressbar_tick:entry           1686523
  3  79504           pkg_absolutepath:entry           1686523
  3  79099         do_extract_regfile:entry           1686523
  3  80433               pkg_get_file:entry           1686523
  3  79095             create_regfile:entry           1686523
  3  79104        pkg_hidden_tempfile:entry           1686523
  3  80494                set_attrsat:entry           1686554
  3  80462                metalog_add:entry           1686554
  3  79584     pkg_emit_progress_tick:entry           1686554
  3  79080             pkg_emit_event:entry           1686554
  3  80542       pkg_plugins_hook_run:entry           1686554
  3  79377             event_callback:entry           1686554
  3  79348           progressbar_tick:entry           1686554
  3  79504           pkg_absolutepath:entry           1686554
  3  79099         do_extract_regfile:entry           1686554
  3  80433               pkg_get_file:entry           1686554
  3  79095             create_regfile:entry           1686554
  3  79104        pkg_hidden_tempfile:entry           1686554
  3  80494                set_attrsat:entry           1686587
  3  80462                metalog_add:entry           1686587
  3  79584     pkg_emit_progress_tick:entry           1686587
  3  79080             pkg_emit_event:entry           1686587
  3  80542       pkg_plugins_hook_run:entry           1686587
  3  79377             event_callback:entry           1686587
  3  79348           progressbar_tick:entry           1686587
  3  79504           pkg_absolutepath:entry           1686587
  3  79100         do_extract_symlink:entry           1686587
  3  80433               pkg_get_file:entry           1686587
  3  79096            create_symlinks:entry           1686587
  3  79104        pkg_hidden_tempfile:entry           1686587
  3  80494                set_attrsat:entry           1686587
  3  80462                metalog_add:entry           1686588
  3  79584     pkg_emit_progress_tick:entry           1686588
  3  79080             pkg_emit_event:entry           1686588
  3  80542       pkg_plugins_hook_run:entry           1686588
  3  79377             event_callback:entry           1686588
  3  79348           progressbar_tick:entry           1686588
  3  79504           pkg_absolutepath:entry           1686588
  3  79100         do_extract_symlink:entry           1686588
  3  80433               pkg_get_file:entry           1686588
  3  79096            create_symlinks:entry           1686588
  3  79104        pkg_hidden_tempfile:entry           1686588
  3  80494                set_attrsat:entry           1686588
  3  80462                metalog_add:entry           1686588
  3  79584     pkg_emit_progress_tick:entry           1686588
  3  79080             pkg_emit_event:entry           1686588
  3  80542       pkg_plugins_hook_run:entry           1686588
  3  79377             event_callback:entry           1686588
  3  79348           progressbar_tick:entry           1686588
  3  79504           pkg_absolutepath:entry           1686588
  3  79100         do_extract_symlink:entry           1686588
  3  80433               pkg_get_file:entry           1686588
  3  79096            create_symlinks:entry           1686588
  3  79104        pkg_hidden_tempfile:entry           1686588
  3  80494                set_attrsat:entry           1686588
  3  80462                metalog_add:entry           1686588
  3  79584     pkg_emit_progress_tick:entry           1686588
  3  79080             pkg_emit_event:entry           1686588
  3  80542       pkg_plugins_hook_run:entry           1686588
  3  79377             event_callback:entry           1686588
  3  79348           progressbar_tick:entry           1686588
  3  79504           pkg_absolutepath:entry           1686588
  3  79100         do_extract_symlink:entry           1686588
  3  80433               pkg_get_file:entry           1686588
  3  79096            create_symlinks:entry           1686588
  3  79104        pkg_hidden_tempfile:entry           1686588
  3  80494                set_attrsat:entry           1686588
  3  80462                metalog_add:entry           1686588
  3  79584     pkg_emit_progress_tick:entry           1686588
  3  79080             pkg_emit_event:entry           1686588
  3  80542       pkg_plugins_hook_run:entry           1686588
  3  79377             event_callback:entry           1686588
  3  79348           progressbar_tick:entry           1686588
  3  79504           pkg_absolutepath:entry           1686588
  3  79100         do_extract_symlink:entry           1686588
  3  80433               pkg_get_file:entry           1686588
  3  79096            create_symlinks:entry           1686588
  3  79104        pkg_hidden_tempfile:entry           1686588
  3  80494                set_attrsat:entry           1686588
  3  80462                metalog_add:entry           1686588
  3  79584     pkg_emit_progress_tick:entry           1686588
  3  79080             pkg_emit_event:entry           1686588
  3  80542       pkg_plugins_hook_run:entry           1686588
  3  79377             event_callback:entry           1686588
  3  79348           progressbar_tick:entry           1686588
  3  79504           pkg_absolutepath:entry           1686588
  3  79100         do_extract_symlink:entry           1686588
  3  80433               pkg_get_file:entry           1686588
  3  79096            create_symlinks:entry           1686588
  3  79104        pkg_hidden_tempfile:entry           1686588
  3  80494                set_attrsat:entry           1686588
  3  80462                metalog_add:entry           1686588
  3  79584     pkg_emit_progress_tick:entry           1686588
  3  79080             pkg_emit_event:entry           1686588
  3  80542       pkg_plugins_hook_run:entry           1686588
  3  79377             event_callback:entry           1686588
  3  79348           progressbar_tick:entry           1686588
  3  79504           pkg_absolutepath:entry           1686588
  3  79099         do_extract_regfile:entry           1686588
  3  80433               pkg_get_file:entry           1686588
  3  79095             create_regfile:entry           1686588
  3  79104        pkg_hidden_tempfile:entry           1686588
  3  80494                set_attrsat:entry           1686620
  3  80462                metalog_add:entry           1686620
  3  79584     pkg_emit_progress_tick:entry           1686620
  3  79080             pkg_emit_event:entry           1686620
  3  80542       pkg_plugins_hook_run:entry           1686620
  3  79377             event_callback:entry           1686620
  3  79348           progressbar_tick:entry           1686620
  3  79504           pkg_absolutepath:entry           1686621
  3  79099         do_extract_regfile:entry           1686621
  3  80433               pkg_get_file:entry           1686621
  3  79095             create_regfile:entry           1686621
  3  79104        pkg_hidden_tempfile:entry           1686621
  3  80494                set_attrsat:entry           1686654
  3  80462                metalog_add:entry           1686654
  3  79584     pkg_emit_progress_tick:entry           1686654
  3  79080             pkg_emit_event:entry           1686654
  3  80542       pkg_plugins_hook_run:entry           1686654
  3  79377             event_callback:entry           1686654
  3  79348           progressbar_tick:entry           1686654
  3  79504           pkg_absolutepath:entry           1686654
  3  79100         do_extract_symlink:entry           1686654
  3  80433               pkg_get_file:entry           1686654
  3  79096            create_symlinks:entry           1686654
  3  79104        pkg_hidden_tempfile:entry           1686654
  3  80494                set_attrsat:entry           1686654
  3  80462                metalog_add:entry           1686654
  3  79584     pkg_emit_progress_tick:entry           1686654
  3  79080             pkg_emit_event:entry           1686654
  3  80542       pkg_plugins_hook_run:entry           1686654
  3  79377             event_callback:entry           1686654
  3  79348           progressbar_tick:entry           1686654
  3  79504           pkg_absolutepath:entry           1686654
  3  79099         do_extract_regfile:entry           1686654
  3  80433               pkg_get_file:entry           1686654
  3  79095             create_regfile:entry           1686654
  3  79104        pkg_hidden_tempfile:entry           1686654
  2  80494                set_attrsat:entry           1686687
  2  80462                metalog_add:entry           1686687
  2  79584     pkg_emit_progress_tick:entry           1686687
  2  79080             pkg_emit_event:entry           1686687
  2  80542       pkg_plugins_hook_run:entry           1686687
  2  79377             event_callback:entry           1686687
  2  79348           progressbar_tick:entry           1686687
  2  79504           pkg_absolutepath:entry           1686687
  2  79100         do_extract_symlink:entry           1686687
  2  80433               pkg_get_file:entry           1686687
  2  79096            create_symlinks:entry           1686687
  2  79104        pkg_hidden_tempfile:entry           1686687
  2  80494                set_attrsat:entry           1686687
  2  80462                metalog_add:entry           1686688
  2  79584     pkg_emit_progress_tick:entry           1686688
  2  79080             pkg_emit_event:entry           1686688
  2  80542       pkg_plugins_hook_run:entry           1686688
  2  79377             event_callback:entry           1686688
  2  79348           progressbar_tick:entry           1686688
  2  79504           pkg_absolutepath:entry           1686688
  2  79100         do_extract_symlink:entry           1686688
  2  80433               pkg_get_file:entry           1686688
  2  79096            create_symlinks:entry           1686688
  2  79104        pkg_hidden_tempfile:entry           1686688
  2  80494                set_attrsat:entry           1686688
  2  80462                metalog_add:entry           1686688
  2  79584     pkg_emit_progress_tick:entry           1686688
  2  79080             pkg_emit_event:entry           1686688
  2  80542       pkg_plugins_hook_run:entry           1686688
  2  79377             event_callback:entry           1686688
  2  79348           progressbar_tick:entry           1686688
  2  79504           pkg_absolutepath:entry           1686688
  2  79099         do_extract_regfile:entry           1686688
  2  80433               pkg_get_file:entry           1686688
  2  79095             create_regfile:entry           1686688
  2  79104        pkg_hidden_tempfile:entry           1686688
  2  80494                set_attrsat:entry           1686720
  2  80462                metalog_add:entry           1686720
  2  79584     pkg_emit_progress_tick:entry           1686720
  2  79080             pkg_emit_event:entry           1686721
  2  80542       pkg_plugins_hook_run:entry           1686721
  2  79377             event_callback:entry           1686721
  2  79348           progressbar_tick:entry           1686721
  2  79504           pkg_absolutepath:entry           1686721
  2  79099         do_extract_regfile:entry           1686721
  2  80433               pkg_get_file:entry           1686721
  2  79095             create_regfile:entry           1686721
  2  79104        pkg_hidden_tempfile:entry           1686721
  2  80494                set_attrsat:entry           1686754
  2  80462                metalog_add:entry           1686754
  2  79584     pkg_emit_progress_tick:entry           1686754
  2  79080             pkg_emit_event:entry           1686754
  2  80542       pkg_plugins_hook_run:entry           1686754
  2  79377             event_callback:entry           1686754
  2  79348           progressbar_tick:entry           1686754
  2  79504           pkg_absolutepath:entry           1686754
  2  79099         do_extract_regfile:entry           1686754
  2  80433               pkg_get_file:entry           1686754
  2  79095             create_regfile:entry           1686754
  2  79104        pkg_hidden_tempfile:entry           1686754
  2  80494                set_attrsat:entry           1686787
  2  80462                metalog_add:entry           1686787
  2  79584     pkg_emit_progress_tick:entry           1686787
  2  79080             pkg_emit_event:entry           1686787
  2  80542       pkg_plugins_hook_run:entry           1686787
  2  79377             event_callback:entry           1686787
  2  79348           progressbar_tick:entry           1686787
  2  79504           pkg_absolutepath:entry           1686787
  2  79100         do_extract_symlink:entry           1686787
  2  80433               pkg_get_file:entry           1686787
  2  79096            create_symlinks:entry           1686787
  2  79104        pkg_hidden_tempfile:entry           1686787
  2  80494                set_attrsat:entry           1686787
  2  80462                metalog_add:entry           1686787
  2  79584     pkg_emit_progress_tick:entry           1686787
  2  79080             pkg_emit_event:entry           1686787
  2  80542       pkg_plugins_hook_run:entry           1686787
  2  79377             event_callback:entry           1686787
  2  79348           progressbar_tick:entry           1686787
  2  79504           pkg_absolutepath:entry           1686787
  2  79100         do_extract_symlink:entry           1686788
  2  80433               pkg_get_file:entry           1686788
  2  79096            create_symlinks:entry           1686788
  2  79104        pkg_hidden_tempfile:entry           1686788
  2  80494                set_attrsat:entry           1686788
  2  80462                metalog_add:entry           1686788
  2  79584     pkg_emit_progress_tick:entry           1686788
  2  79080             pkg_emit_event:entry           1686788
  2  80542       pkg_plugins_hook_run:entry           1686788
  2  79377             event_callback:entry           1686788
  2  79348           progressbar_tick:entry           1686788
  2  79504           pkg_absolutepath:entry           1686788
  2  79100         do_extract_symlink:entry           1686788
  2  80433               pkg_get_file:entry           1686788
  2  79096            create_symlinks:entry           1686788
  2  79104        pkg_hidden_tempfile:entry           1686788
  2  80494                set_attrsat:entry           1686788
  2  80462                metalog_add:entry           1686788
  2  79584     pkg_emit_progress_tick:entry           1686788
  2  79080             pkg_emit_event:entry           1686788
  2  80542       pkg_plugins_hook_run:entry           1686788
  2  79377             event_callback:entry           1686788
  2  79348           progressbar_tick:entry           1686788
  2  79504           pkg_absolutepath:entry           1686788
  2  79099         do_extract_regfile:entry           1686788
  2  80433               pkg_get_file:entry           1686788
  2  79095             create_regfile:entry           1686788
  2  79104        pkg_hidden_tempfile:entry           1686788
  2  80494                set_attrsat:entry           1686820
  2  80462                metalog_add:entry           1686821
  2  79584     pkg_emit_progress_tick:entry           1686821
  2  79080             pkg_emit_event:entry           1686821
  2  80542       pkg_plugins_hook_run:entry           1686821
  2  79377             event_callback:entry           1686821
  2  79348           progressbar_tick:entry           1686821
  2  79504           pkg_absolutepath:entry           1686821
  2  79100         do_extract_symlink:entry           1686821
  2  80433               pkg_get_file:entry           1686821
  2  79096            create_symlinks:entry           1686821
  2  79104        pkg_hidden_tempfile:entry           1686821
  2  80494                set_attrsat:entry           1686821
  2  80462                metalog_add:entry           1686821
  2  79584     pkg_emit_progress_tick:entry           1686821
  2  79080             pkg_emit_event:entry           1686821
  2  80542       pkg_plugins_hook_run:entry           1686821
  2  79377             event_callback:entry           1686821
  2  79348           progressbar_tick:entry           1686821
  2  79504           pkg_absolutepath:entry           1686821
  2  79100         do_extract_symlink:entry           1686821
  2  80433               pkg_get_file:entry           1686821
  2  79096            create_symlinks:entry           1686821
  2  79104        pkg_hidden_tempfile:entry           1686821
  2  80494                set_attrsat:entry           1686821
  2  80462                metalog_add:entry           1686821
  2  79584     pkg_emit_progress_tick:entry           1686821
  2  79080             pkg_emit_event:entry           1686821
  2  80542       pkg_plugins_hook_run:entry           1686821
  2  79377             event_callback:entry           1686821
  2  79348           progressbar_tick:entry           1686821
  2  79504           pkg_absolutepath:entry           1686821
  2  79100         do_extract_symlink:entry           1686821
  2  80433               pkg_get_file:entry           1686821
  2  79096            create_symlinks:entry           1686821
  2  79104        pkg_hidden_tempfile:entry           1686821
  2  80494                set_attrsat:entry           1686821
  2  80462                metalog_add:entry           1686821
  2  79584     pkg_emit_progress_tick:entry           1686821
  2  79080             pkg_emit_event:entry           1686821
  2  80542       pkg_plugins_hook_run:entry           1686821
  2  79377             event_callback:entry           1686821
  2  79348           progressbar_tick:entry           1686821
  2  79504           pkg_absolutepath:entry           1686821
  2  79099         do_extract_regfile:entry           1686821
  2  80433               pkg_get_file:entry           1686821
  2  79095             create_regfile:entry           1686821
  2  79104        pkg_hidden_tempfile:entry           1686821
  2  80494                set_attrsat:entry           1686854
  2  80462                metalog_add:entry           1686854
  2  79584     pkg_emit_progress_tick:entry           1686854
  2  79080             pkg_emit_event:entry           1686854
  2  80542       pkg_plugins_hook_run:entry           1686854
  2  79377             event_callback:entry           1686854
  2  79348           progressbar_tick:entry           1686854
  2  79504           pkg_absolutepath:entry           1686854
  2  79100         do_extract_symlink:entry           1686854
  2  80433               pkg_get_file:entry           1686854
  2  79096            create_symlinks:entry           1686854
  2  79104        pkg_hidden_tempfile:entry           1686854
  2  80494                set_attrsat:entry           1686854
  2  80462                metalog_add:entry           1686854
  2  79584     pkg_emit_progress_tick:entry           1686854
  2  79080             pkg_emit_event:entry           1686854
  2  80542       pkg_plugins_hook_run:entry           1686854
  2  79377             event_callback:entry           1686854
  2  79348           progressbar_tick:entry           1686854
  2  79504           pkg_absolutepath:entry           1686854
  2  79099         do_extract_regfile:entry           1686854
  2  80433               pkg_get_file:entry           1686854
  2  79095             create_regfile:entry           1686854
  2  79104        pkg_hidden_tempfile:entry           1686854
```

Does this tell anything to you?


----------



## shkhln (Nov 23, 2020)

Dendros said:


> Does this tell anything to you?


As you can see, there are occasional 32 ms jumps after pkg_hidden_tempfile. Here is the same script with the dtrace part modified to log functions invoked between pkg_hidden_tempfile and set_attrsat:

```
#!/usr/bin/env ruby
# encoding: UTF-8

DT_SCRIPT = <<~E
  pid$target:pkg:pkg_hidden_tempfile:entry {
    printf("----------");
    self->traceme = 1;
  }
  pid$target:pkg:set_attrsat:entry {
    printf("^^^^^^^^^^");
    self->traceme = 0;
  }
  pid$target:::entry  /self->traceme/ { trace(timestamp / 1000000); }
  pid$target:::return /self->traceme/ { trace(timestamp / 1000000); }
E

system('mkfifo /tmp/pkg.events')

threads = []

threads << Thread.new do
  File.open('/tmp/pkg.events').each_line do |line|
    case line
      when /INFO_EXTRACT_BEGIN/
        system('pkill -SIGSTOP pkg')
        pid = `pgrep pkg`.lines.first.chomp.to_i # might not be the correct pid, YMMV
        threads << Thread.new do
          system("dtrace -n '#{DT_SCRIPT.lines.map(&:chomp).join(' ')}' -p #{pid}")
        end
        sleep 1
        system('pkill -SIGCONT pkg')
      when /INFO_EXTRACT_FINISHED/
        system('pkill dtrace')
        break
    end
  end
end

system('env EVENT_PIPE=/tmp/pkg.events pkg install -fy papirus-icon-theme')

threads.each do |t|
  t.join
end
```
Also, this forum supports [spoiler]a lot of text[/spoiler] notation.


----------



## Dendros (Nov 23, 2020)

OK, ran the second version of your script. This time, it was interesting, in that suddenly `dtrace` decided to stop displaying messages - without me doing anything other than stare at screen - and the extraction of the package continued but the debug messages were no longer displayed so I decided to stop the entire process since it seemed pointless to continue without those messages.

The forum did not allow me to enter the entire body of the report, even within spoiler tags, so I saved it as a compressed file and attached it.


----------



## shkhln (Nov 23, 2020)

So, apparently _ftruncate_ is somewhat slow on that system. Maybe https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=219049 is relevant to your problem?


----------



## Dendros (Nov 23, 2020)

This bug seems similar to what I'm experiencing but then why does this problem disappear after replacing the HDD on the main system?


----------



## shkhln (Nov 23, 2020)

Dendros said:


> but then why does this problem disappear after replacing the HDD on the main system?


Is that some kind of a joke?


----------



## Dendros (Nov 23, 2020)

No, but I should clarify: this problem first appeared on my main system (the FX 8350 based system) with 4 HDDs installed into it, one of them being a Toshiba drive with FreeBSD installed on it.
Because I was frustrated with this whole situation, I have replaced the Toshiba drive with a Hitachi one and reinstalled FreeBSD on that new disk and this problem no longer appears after that - the install times are much more reasonable now on my main system, I have posted a `time` report.


But I have another system, a HP with a 250 GB HDD which also had FreeBSD on it and on that configuration pkg's install times were also normal, not slow (tested it too).
Well, I replaced that 250 GB HDD with the Toshiba drive that was taken out of the main system, reinstalled FreeBSD on it and the problem with pkg appeared again. Then I decided to continue testing but this time on the HP.
So, all of your tests were done on that HP with that Toshiba since it seems that this drive is good, not defective and yet pkg behaves the way it did on the main system.

Is it more clear now?


----------



## olli@ (Nov 24, 2020)

Dendros said:


> This bug seems similar to what I'm experiencing but then why does this problem disappear after replacing the HDD on the main system?


That bug is only triggered when _journaled softupdates_ is enabled on a UFS filesystem. Is that the case for your Toshiba disk? If so, please disable journaling for that file system, i.e. run `tunefs -j disable /dev/whatever` while the file system is not mounted (or mounted read-only), see the tunefs(8) manual page for details. Then check if the problem persists.


----------



## Dendros (Nov 24, 2020)

olli@: did as you suggested, disabled journaling (`tunefs -j disable /dev/ada0s1a`) on that Toshiba drive but still no change, still slow extracting with `pkg`.

But, just for the heck of it, I decided to reinstall FreeBSD on the HP with the Toshiba drive but this time with ZFS as the file system.
And, lo and behold, much better install times:


```
# time pkg install flat-remix-icon-themes
Updating FreeBSD repository catalogue...
FreeBSD repository is up to date.
All repositories are up to date.
The following 1 package(s) will be affected (of 0 checked):

New packages to be INSTALLED:
    flat-remix-icon-themes: 20201112

Number of packages to be installed: 1

The process will require 273 MiB more space.
38 MiB to be downloaded.

Proceed with this action? [y/N]: y
[1/1] Fetching flat-remix-icon-themes-20201112.txz:   5%    2 MiB   2.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201112.txz:  12%    5 MiB   2.9MB/s    0[1/1] Fetching flat-remix-icon-themes-20201112.txz:  19%    8 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201112.txz:  27%   10 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201112.txz:  34%   13 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201112.txz:  42%   16 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201112.txz:  49%   19 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201112.txz:  57%   22 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201112.txz:  64%   25 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201112.txz:  72%   28 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201112.txz:  79%   31 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201112.txz:  87%   33 MiB   3.1MB/s    0[1/1] Fetching flat-remix-icon-themes-20201112.txz:  94%   36 MiB   3.0MB/s    0[1/1] Fetching flat-remix-icon-themes-20201112.txz: 100%   38 MiB   3.1MB/s    00:13   
Checking integrity... done (0 conflicting)
[1/1] Installing flat-remix-icon-themes-20201112...
[1/1] Extracting flat-remix-icon-themes-20201112: 100%
19.065u 40.813s 1:16.03 78.7%    2651+29060k 159353+81538io 15pf+0w
```
Although with a lot higher CPU usage, if I understand it correctly.

It seems it's indeed a bug involving `pkg` and UFS but why does this bug not manifest on the Hitachi drive in the main system which also has FreeBSD with UFS? It's possible that this bug (if it's a bug) only triggers on some brands/models of drives?

It's really weird.


----------



## facedebouc (Nov 25, 2020)

Does your UFS filesystem on the Toshiba HDD had soft updates enabled ?
You can verify with the `mount` command.


----------



## olli@ (Nov 25, 2020)

Dendros said:


> It seems it's indeed a bug involving `pkg` and UFS but why does this bug not manifest on the Hitachi drive in the main system which also has FreeBSD with UFS? It's possible that this bug (if it's a bug) only triggers on some brands/models of drives?


Well, different drives may behave differently, regarding the behavior of write-back caches, ordering of queued tags (when NCQ is supported) and other details in the firmware. Even if drives have the same size of cache, the firmware can manage it in different ways.


----------



## Dendros (Nov 25, 2020)

olli@: I think you're right. Would FreeBSD 12.2 be better (i.e without this problem)? I haven't upgraded to it yet because of the bug with drm-kmod.

facedebouc: yes, soft-updates were enabled on the Toshiba drive (they're enabled by default) but I have disabled journaling as per olli@'s advice and no change, the problem was still present. Now I have ZFS on that drive and, as I showed above, the problem no longer appears.


----------



## olli@ (Nov 26, 2020)

Dendros said:


> olli@: I think you're right. Would FreeBSD 12.2 be better (i.e without this problem)? I haven't upgraded to it yet because of the bug with drm-kmod.


Difficult to to tell … If the performance problem is caused by a firmware issue that is triggered by UFS, then an upgrade won’t change it, I’m afraid. By the way, I wouldn’t call it a “bug”; maybe it is just an unfortunate interaction between the drive firmware and the UFS code.

ZFS works very different from UFS. It is a COW file system (copy-on-write) and handles write-barriers and tags differently from UFS, which means that it also uses the drive’s cache differently. So maybe it doesn’t trigger the firmware issue, and that’s why this particular problem is mitigated when you switch to ZFS.

All of that is just speculation, of course, but it doesn’t sound unlikely.


----------

