HDD problems or something else?

olli@ · Nov 17, 2020

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 [USER=52756]PMc[/USER]'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 [USER=52756]PMc[/USER]'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 [USER=52756]PMc[/USER]'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
a lot of reading and writing could occur in /var/tmp. By properly
partitioning your system fragmentation introduced in the smaller more
heavily write-loaded partitions will not bleed over into the mostly-read
partitions.

(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:

Code:

# 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):

Code:

# 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):

Code:

# 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):

Code:

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

[USER=54069]shkhln[/USER]: 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:

Code:

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:

Code:

# 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:

Code:

$ 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?

[USER=52756]PMc[/USER]: 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:

Code:

#!/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:

Code:


  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

[USER=54069]shkhln[/USER]: 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 [user=54069]Shkhln[/user], but I'll take a crack at it anyway

Code:

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

Create a named pipe at /tmp/pkg.events

Code:

threads = []

Create an empty list of threads

Code:

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.

Code:

    case line
      when /INFO_EXTRACT_BEGIN/

If the line contains the text "INFO_EXTRACT_BEGIN"

Code:

        system('pkill -SIGSTOP pkg')

Send the STOP signal to any process called "pkg" using pkill(1)

Code:

        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"

Code:

        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.

Code:

        sleep 1
        system('pkill -SIGCONT pkg')

Sleep for one second and then send the CONT signal to the pkg process

Code:

      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.

Code:

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.

Code:

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".

Code:

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

[USER=33252]Jose[/USER]: 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:

Code:

  
  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:

Code:

#!/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.

HDD problems or something else?

Aspiring Daemon

Son of Beastie

Member

Son of Beastie

Daemon

Daemon

Aspiring Daemon

Aspiring Daemon

Daemon

Aspiring Daemon

Daemon

Aspiring Daemon

Member

Daemon

Member

Son of Beastie

Daemon

Aspiring Daemon

Member

Daemon

Member

Aspiring Daemon

Member

Member

Daemon