Question Response to ATA command is very slow with HDD and AHCI SATA controller configuration ?

[kumarrahul007]

Hi,

I have a laptop with an M.2 SSD and a Seagate 500GB HDD.
BIOS SATA/NVMe Operation is configured to AHCI/NVMe.
Windows 11 and IDE ATA/ATAPI controllers, Standard SATA AHCI Controller, version 10.0.22621.2506.

Application is trying to send ATA commands but the response for the same is very slow (at times more than 10 mins).
IOCTL IOCTL_ATA_PASS_THROUGH_DIRECT is send using WIN32API DeviceIoControl() API. The ATA register is configured to send ATA command, ATA_CMD_SMART, and sub command, SMART_READ_LOG.

Any idea why response from driver is taking so much time?

Regards,

 

[Ralston18]

Not something I am familar with (full disclosure) but three immediate questions:

1) What "application" is trying to send?

2) What specifc commands are being sent with what purpose(s)?

3) The ATA commands eventually work even if the response is slow - correct?

 

[fzabkar]

Do GSmartControl and CrystalDiskInfo have the same problem?

 

[kumarrahul007]

Not something I am familar with (full disclosure) but three immediate questions:

1) What "application" is trying to send?

2) What specifc commands are being sent with what purpose(s)?

3) The ATA commands eventually work even if the response is slow - correct?

Hi,
1) What "application" is trying to send?
It's a cpp application trying to get the ATA/AHCI controller info (e.g. device ID etc.) and devices information (e.g. device ID etc.) connected to it.

2) What specifc commands are being sent with what purpose(s)?
commands is mentioned above. I am trying to send ATA command, ATA_CMD_SMART, and sub command, SMART_READ_LOG using IOCTL IOCTL_ATA_PASS_THROUGH_DIRECT.

3) The ATA commands eventually work even if the response is slow - correct?
yes, the command eventually works but I have to wait for anywhere between 10-30 mins.

 

[Ralston18]

How big are the logs?

Also - any answer for @fzabkar per Post #3?

 

[kumarrahul007]

Do GSmartControl and CrystalDiskInfo have the same problem?

Hi,

both tools are showing the health of HDD is good. And did not observe any huge lag (test completed with 3 mins) when executed self-test.

--------------------------------------------------------------------------------------
smartctl 7.2 2020-12-30 r5155 [x86_64-w64-mingw32-w10-b22621] (sf-7.2-1)
Copyright (C) 2002-20, Bruce Allen, Christian Franke, www.smartmontools.org

=== START OF INFORMATION SECTION ===
Model Family: Seagate Barracuda 2.5 5400
Device Model: ST500LM030-1RK17D
Serial Number: WKP6BVWX
LU WWN Device Id: 5 000c50 0cc92fb67
Firmware Version: 0001
User Capacity: 500,107,862,016 bytes [500 GB]
Sector Sizes: 512 bytes logical, 4096 bytes physical
Rotation Rate: 5400 rpm
Form Factor: 2.5 inches
TRIM Command: Available
Device is: In smartctl database [for details use: -P show]
ATA Version is: ACS-3 T13/2161-D revision 3b
SATA Version is: SATA 3.1, 6.0 Gb/s (current: 6.0 Gb/s)
Local Time is: Tue Jan 30 17:32:12 2024 CST
SMART support is: Available - device has SMART capability.
SMART support is: Enabled
AAM feature is: Unavailable
APM level is: 128 (minimum power consumption without standby)
Rd look-ahead is: Enabled
Write cache is: Enabled
DSN feature is: Unavailable
ATA Security is: Disabled, frozen [SEC2]

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

General SMART Values:
Offline data collection status: (0x00) Offline data collection activity
was never started.
Auto Offline Data Collection: Disabled.
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: ( 0) seconds.
Offline data collection
capabilities: (0x71) SMART execute Offline immediate.
No Auto Offline data collection support.
Suspend Offline collection upon new
command.
No Offline surface scan supported.
Self-test supported.
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: ( 78) minutes.
Conveyance self-test routine
recommended polling time: ( 2) minutes.
SCT capabilities: (0x3035) SCT Status supported.
SCT Feature Control supported.
SCT Data Table supported.

SMART Attributes Data Structure revision number: 10
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME FLAGS VALUE WORST THRESH FAIL RAW_VALUE
1 Raw_Read_Error_Rate POSR-- 083 064 006 - 195875665
3 Spin_Up_Time PO---- 099 099 000 - 0
4 Start_Stop_Count -O--CK 100 100 020 - 269
5 Reallocated_Sector_Ct PO--CK 100 100 036 - 0
7 Seek_Error_Rate POSR-- 066 060 045 - 4302385
9 Power_On_Hours -O--CK 100 100 000 - 278 (221 125 0)
10 Spin_Retry_Count PO--C- 100 100 097 - 0
12 Power_Cycle_Count -O--CK 100 100 020 - 236
184 End-to-End_Error -O--CK 100 100 099 - 0
187 Reported_Uncorrect -O--CK 100 100 000 - 0
188 Command_Timeout -O--CK 100 100 000 - 0
189 High_Fly_Writes -O-RCK 100 100 000 - 0
190 Airflow_Temperature_Cel -O---K 072 042 040 - 28 (Min/Max 25/28)
191 G-Sense_Error_Rate -O--CK 100 100 000 - 6
192 Power-Off_Retract_Count -O--CK 100 100 000 - 98
193 Load_Cycle_Count -O--CK 098 098 000 - 5094
194 Temperature_Celsius -O---K 028 058 000 - 28 (0 17 0 0 0)
197 Current_Pending_Sector -O--C- 100 100 000 - 0
198 Offline_Uncorrectable ----C- 100 100 000 - 0
199 UDMA_CRC_Error_Count -OSRCK 200 200 000 - 3
240 Head_Flying_Hours ------ 100 253 000 - 179 (252 138 0)
241 Total_LBAs_Written ------ 100 253 000 - 756659287
242 Total_LBAs_Read ------ 100 253 000 - 659919988
254 Free_Fall_Sensor -O--CK 001 001 000 - 2
||||||_ K auto-keep
|||||__ C event count
||||___ R error rate
|||____ S speed/performance
||_____ O updated online
|______ P prefailure warning

General Purpose Log Directory Version 1
SMART Log Directory Version 1 [multi-sector log support]
Address Access R/W Size Description
0x00 GPL,SL R/O 1 Log Directory
0x01 SL R/O 1 Summary SMART error log
0x02 SL R/O 5 Comprehensive SMART error log
0x03 GPL R/O 5 Ext. Comprehensive SMART error log
0x04 GPL,SL R/O 8 Device Statistics log
0x06 SL R/O 1 SMART self-test log
0x07 GPL R/O 1 Extended self-test log
0x09 SL R/W 1 Selective self-test log
0x10 GPL R/O 1 NCQ Command Error log
0x11 GPL R/O 1 SATA Phy Event Counters log
0x21 GPL R/O 1 Write stream error log
0x22 GPL R/O 1 Read stream error log
0x24 GPL R/O 512 Current Device Internal Status Data log
0x30 GPL,SL R/O 9 IDENTIFY DEVICE data log
0x80-0x9f GPL,SL R/W 16 Host vendor specific log
0xa1 GPL,SL VS 24 Device vendor specific log
0xa2 GPL VS 8160 Device vendor specific log
0xa8 GPL,SL VS 136 Device vendor specific log
0xa9 GPL,SL VS 1 Device vendor specific log
0xab GPL VS 1 Device vendor specific log
0xb0 GPL VS 8920 Device vendor specific log
0xbe-0xbf GPL VS 65535 Device vendor specific log
0xc0 GPL,SL VS 1 Device vendor specific log
0xc1 GPL,SL VS 16 Device vendor specific log
0xc2 GPL,SL VS 240 Device vendor specific log
0xc3 GPL,SL VS 8 Device vendor specific log
0xc4 GPL,SL VS 24 Device vendor specific log
0xd3 GPL VS 1920 Device vendor specific log
0xe0 GPL,SL R/W 1 SCT Command/Status
0xe1 GPL,SL R/W 1 SCT Data Transfer

SMART Extended Comprehensive Error Log Version: 1 (5 sectors)
No Errors Logged

SMART Extended Self-test Log Version: 1 (1 sectors)
Num Test_Description Status Remaining LifeTime(hours) LBA_of_first_error
# 1 Short offline Completed without error 00% 278 -
# 2 Conveyance offline Completed without error 00% 275 -
# 3 Short offline Completed without error 00% 275 -
# 4 Short offline Completed without error 00% 51 -
# 5 Short offline Completed without error 00% 51 -
# 6 Short offline Completed without error 00% 51 -
# 7 Short offline Completed without error 00% 51 -
# 8 Short offline Completed without error 00% 26 -

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.

SCT Status Version: 3
SCT Version (vendor specific): 522 (0x020a)
Device State: Active (0)
Current Temperature: 28 Celsius
Power Cycle Min/Max Temperature: 25/28 Celsius
Lifetime Min/Max Temperature: 17/53 Celsius
Specified Max Operating Temperature: 29 Celsius
Under/Over Temperature Limit Count: 0/0

SCT Temperature History Version: 2
Temperature Sampling Period: 1 minute
Temperature Logging Interval: 30 minutes
Min/Max recommended Temperature: 14/55 Celsius
Min/Max Temperature Limit: 10/60 Celsius
Temperature History Size (Index): 128 (126)

Index Estimated Time Temperature Celsius
127 2024-01-28 02:00 ? -
0 2024-01-28 02:30 23 ****
1 2024-01-28 03:00 ? -
2 2024-01-28 03:30 23 ****
3 2024-01-28 04:00 ? -
4 2024-01-28 04:30 24 *****
5 2024-01-28 05:00 ? -
6 2024-01-28 05:30 22 ***
7 2024-01-28 06:00 ? -
8 2024-01-28 06:30 23 ****
9 2024-01-28 07:00 ? -
10 2024-01-28 07:30 23 ****
11 2024-01-28 08:00 ? -
12 2024-01-28 08:30 23 ****
13 2024-01-28 09:00 ? -
14 2024-01-28 09:30 23 ****
15 2024-01-28 10:00 ? -
16 2024-01-28 10:30 23 ****
17 2024-01-28 11:00 ? -
18 2024-01-28 11:30 24 *****
19 2024-01-28 12:00 ? -
20 2024-01-28 12:30 24 *****
21 2024-01-28 13:00 ? -
22 2024-01-28 13:30 24 *****
23 2024-01-28 14:00 ? -
24 2024-01-28 14:30 26 *******
25 2024-01-28 15:00 ? -
26 2024-01-28 15:30 29 **********
27 2024-01-28 16:00 ? -
28 2024-01-28 16:30 29 **********
29 2024-01-28 17:00 ? -
30 2024-01-28 17:30 29 **********
31 2024-01-28 18:00 ? -
32 2024-01-28 18:30 30 ***********
33 2024-01-28 19:00 ? -
34 2024-01-28 19:30 24 *****
35 2024-01-28 20:00 ? -
36 2024-01-28 20:30 24 *****
37 2024-01-28 21:00 ? -
38 2024-01-28 21:30 27 ********
39 2024-01-28 22:00 ? -
40 2024-01-28 22:30 27 ********
41 2024-01-28 23:00 ? -
42 2024-01-28 23:30 28 *********
43 2024-01-29 00:00 ? -
44 2024-01-29 00:30 22 ***
45 2024-01-29 01:00 ? -
46 2024-01-29 01:30 23 ****
47 2024-01-29 02:00 ? -
48 2024-01-29 02:30 23 ****
49 2024-01-29 03:00 ? -
50 2024-01-29 03:30 24 *****
51 2024-01-29 04:00 ? -
52 2024-01-29 04:30 24 *****
53 2024-01-29 05:00 ? -
54 2024-01-29 05:30 25 ******
55 2024-01-29 06:00 ? -
56 2024-01-29 06:30 24 *****
57 2024-01-29 07:00 ? -
58 2024-01-29 07:30 24 *****
59 2024-01-29 08:00 ? -
60 2024-01-29 08:30 25 ******
61 2024-01-29 09:00 ? -
62 2024-01-29 09:30 25 ******
63 2024-01-29 10:00 ? -
64 2024-01-29 10:30 23 ****
65 2024-01-29 11:00 ? -
66 2024-01-29 11:30 24 *****
67 2024-01-29 12:00 ? -
68 2024-01-29 12:30 25 ******
69 2024-01-29 13:00 ? -
70 2024-01-29 13:30 25 ******
71 2024-01-29 14:00 ? -
72 2024-01-29 14:30 25 ******
73 2024-01-29 15:00 ? -
74 2024-01-29 15:30 27 ********
75 2024-01-29 16:00 ? -
76 2024-01-29 16:30 20 *
77 2024-01-29 17:00 ? -
78 2024-01-29 17:30 22 ***
79 2024-01-29 18:00 ? -
80 2024-01-29 18:30 24 *****
81 2024-01-29 19:00 ? -
82 2024-01-29 19:30 24 *****
83 2024-01-29 20:00 ? -
84 2024-01-29 20:30 24 *****
85 2024-01-29 21:00 ? -
86 2024-01-29 21:30 23 ****
87 2024-01-29 22:00 ? -
88 2024-01-29 22:30 19 -
89 2024-01-29 23:00 ? -
90 2024-01-29 23:30 19 -
91 2024-01-30 00:00 ? -
92 2024-01-30 00:30 26 *******
93 2024-01-30 01:00 ? -
94 2024-01-30 01:30 27 ********
95 2024-01-30 02:00 ? -
96 2024-01-30 02:30 23 ****
97 2024-01-30 03:00 ? -
98 2024-01-30 03:30 23 ****
99 2024-01-30 04:00 ? -
100 2024-01-30 04:30 26 *******
101 2024-01-30 05:00 ? -
102 2024-01-30 05:30 26 *******
103 2024-01-30 06:00 ? -
104 2024-01-30 06:30 34 ***************
105 2024-01-30 07:00 ? -
106 2024-01-30 07:30 28 *********
107 2024-01-30 08:00 ? -
108 2024-01-30 08:30 24 *****
109 2024-01-30 09:00 ? -
110 2024-01-30 09:30 25 ******
111 2024-01-30 10:00 ? -
112 2024-01-30 10:30 27 ********
113 2024-01-30 11:00 ? -
114 2024-01-30 11:30 28 *********
115 2024-01-30 12:00 ? -
116 2024-01-30 12:30 27 ********
117 2024-01-30 13:00 ? -
118 2024-01-30 13:30 22 ***
119 2024-01-30 14:00 ? -
120 2024-01-30 14:30 23 ****
121 2024-01-30 15:00 ? -
122 2024-01-30 15:30 25 ******
... ..( 3 skipped). .. ******
126 2024-01-30 17:30 25 ******

SCT Error Recovery Control command not supported

Device Statistics (GP Log 0x04)
Page Offset Size Value Flags Description
0x01 ===== = = === == General Statistics (rev 1) ==
0x01 0x008 4 236 --- Lifetime Power-On Resets
0x01 0x010 4 278 --- Power-on Hours
0x01 0x018 6 756498346 --- Logical Sectors Written
0x01 0x020 6 7636340 --- Number of Write Commands
0x01 0x028 6 658570346 --- Logical Sectors Read
0x01 0x030 6 6863975 --- Number of Read Commands
0x01 0x038 6 1706657533805 --- Date and Time TimeStamp
0x03 ===== = = === == Rotating Media Statistics (rev 1) ==
0x03 0x008 4 2337644509 N-- Spindle Motor Power-on Hours
0x03 0x010 4 2337644374 N-- Head Flying Hours
0x03 0x018 4 5095 --- Head Load Events
0x03 0x020 4 0 --- Number of Reallocated Logical Sectors
0x03 0x028 4 0 --- Read Recovery Attempts
0x03 0x030 4 0 --- Number of Mechanical Start Failures
0x03 0x038 4 0 --- Number of Realloc. Candidate Logical Sectors
0x04 ===== = = === == General Errors Statistics (rev 1) ==
0x04 0x008 4 0 --- Number of Reported Uncorrectable Errors
0x04 0x010 4 0 --- Resets Between Cmd Acceptance and Completion
|||_ C monitored condition met
||__ D supports DSN
|___ N normalized value

SATA Phy Event Counters (GP Log 0x11)
ID Size Value Description
0x000a 2 3 Device-to-host register FISes sent due to a COMRESET
0x0001 2 0 Command failed due to ICRC error
0x0003 2 0 R_ERR response for device-to-host data FIS
0x0004 2 0 R_ERR response for host-to-device data FIS
0x0006 2 0 R_ERR response for device-to-host non-data FIS
0x0007 2 0 R_ERR response for host-to-device non-data FIS
-----------------------------------------------------------------------------------------

 

[kumarrahul007]

How big are the logs?

Also - any answer for @fzabkar per Post #3?

Logs.
responded to Post 3 as well.
--------------------------------------------------------------------------------------
HDD0 NVMe SMART Log Attributes
Critical Warnings : 00
Temperature (kelvin) : 308
Percent Available Spare : 100
Percent Available Spare Threshold : 50
Life Percentage Used : 0
Data Units Read : 0x0000000000182995
Data Units Written : 0x0000000000160a5b
Host Read Commands : 0x0000000000eeeab2
Host Write Commands : 0x0000000000cc0b44
Controller Busy Time : 0x00000000000000d3
Power Cycles : 0x00000000000000a7
Power On Hours : 0x0000000000000069
Unsafe Shutdowns : 0x000000000000006e
Media Errors : 0x0000000000000000
Number of Error Log Entries : 0x0000000000000000
Warning Time Over Temp (minutes) : 0
Critical Time Over Temp (minutes) : 0
Temperature Sensor 1 : 308
Temperature Sensor 2 : 0
Temperature Sensor 3 : 0
Temperature Sensor 4 : 0
Temperature Sensor 5 : 0
Temperature Sensor 6 : 0
Temperature Sensor 7 : 0
Temperature Sensor 8 : 0
Therm Mgmt Temp 1 Transition Count : 0
Therm Mgmt Temp 2 Transition Count : 0
Therm Mgmt Temp 1 Total Time (sec) : 0
Therm Mgmt Temp 2 Total Time (sec) : 0

-----------------------------------------------------------------------------------------

 

[Ralston18]

Those are log attributes.

However, the "Number of Error Log Entries:" appears to be 0 (zero) - not what I would expect.

Are you able to find and access specific logs?

Reference:

"General Purpose Log Directory Version 1" (Noted in Post #6),

Going out of my comfort zone (full disclosure) but within the overall context if the commands require lots of time to work/finish (barring some coding issue) then there may be lots of data being processed.

 

[fzabkar]

There are no Command Timeouts, and it appears that GSmartControl is able to read all the supported SMART logs without delay. ISTM that the problem must be on the host side rather than the drives themselves.

 

[kumarrahul007]

Those are log attributes.

However, the "Number of Error Log Entries:" appears to be 0 (zero) - not what I would expect.

Are you able to find and access specific logs?

Reference:

"General Purpose Log Directory Version 1" (Noted in Post #6),

Going out of my comfort zone (full disclosure) but within the overall context if the commands require lots of time to work/finish (barring some coding issue) then there may be lots of data being processed.

I do not see huge data transferred. e.g. I set the registry to get the temperature by setting registry for SCT_CMD_STATUS command. for this, response time are for 4 retirees: 2min, 2min, 4min, 32min.

the response received is in a buffer which has temp data. The buffer size must be max 512 (need to verify though).

 

[kumarrahul007]

There are no Command Timeouts, and it appears that GSmartControl is able to read all the supported SMART logs without delay. ISTM that the problem must be on the host side rather than the drives themselves.

Thanks for narrowing down.

I was wondering how GSmartControl is getting SMART logs. It also must be using the ATA commands right. So, essentially same driver, ahcistor, to access the controller?

 

[fzabkar]

0x24 GPL R/O 512 Current Device Internal Status Data log

This is the largest log that you can access. Its size is 512 sectors.

The "Device vendor specific logs" are Seagate's internal logs. The drive needs to be placed in "techno mode" before it will allow access to these logs. This is done by sending a special "VSC Enable" command (VSC = Vendor Specific Commands). IIUC, logs 0xBE and 0xBF are the means by which firmware modules are read and written to or from the ROM or platters (plus other functions).

 

[fzabkar]

Thanks for narrowing down.

I was wondering how GSmartControl is getting SMART logs. It also must be using the ATA commands right. So, essentially same driver, ahcistor, to access the controller?

I think there are two ways in which GSmartControl can access the drive. I'm not a programmer, so I cannot elaborate. However, the author of smartctl (Christian Franke) will probably answer any questions via the smartmontools mailing list.

Edit:

I think there are two command sets in the ATA standard. One is GPL, the other is SCT Command Transport. They essentially do the same thing, but go about it in different ways, AIUI.

Edit #2:

I just looked up the ATA standard.

SCT data transfer using the SMART feature set

D6h (i.e., SMART WRITE LOG (see 7.48.9))
D5h (i.e., SMART READ LOG (see 7.48.7))


SCT data transfer using the GPL feature set

2Fh (i.e., READ LOG EXT (see 7.24))
47h (i.e., READ LOG DMA EXT (see 7.25))
3Fh (i.e., WRITE LOG EXT (see 7.62))
57h (i.e., WRITE LOG DMA EXT (see 7.63))

 

[Ralston18]

Will defer to @fzabkar because I am going well out of my comfort zones.

However, I am still willing to ask questions and learn.

The commands are running but end results are slow - that remains true - correct?

Are the commands being run via some sort of script or macro?

Is it possible to add some commands that display results, actions, etc, that are taking place (or should be taking place) as the commands progress?

In other words be able view the ongoing progress. Objective simply to determine where things bog down.

For example, if something is READ, then show/display what is READ.

Or report when some part of the script has completed.

Not uncommon to use such methods to debug code. Then simply comment out the commands doing so,

Maybe even create another log to capture and store actions that can report progress.

Something like:

https://www.stbsuite.com/support/vi...used to,consisted of seven separate registers.

http://www.scsitoolbox.com/Products/ATATaskRegisterCommands.asp

Reference "Command Results History". Discover what is happening or not.

Just thinking out loud.

 

[kumarrahul007]

Will defer to @fzabkar because I am going well out of my comfort zones.

However, I am still willing to ask questions and learn.

The commands are running but end results are slow - that remains true - correct?

Are the commands being run via some sort of script or macro?

Is it possible to add some commands that display results, actions, etc, that are taking place (or should be taking place) as the commands progress?

In other words be able view the ongoing progress. Objective simply to determine where things bog down.

For example, if something is READ, then show/display what is READ.

Or report when some part of the script has completed.

Not uncommon to use such methods to debug code. Then simply comment out the commands doing so,

Maybe even create another log to capture and store actions that can report progress.

Something like:

https://www.stbsuite.com/support/virtual-training-center/issuing-ata-commands#:~:text=ATA commands are used to,consisted of seven separate registers.

http://www.scsitoolbox.com/Products/ATATaskRegisterCommands.asp

Reference "Command Results History". Discover what is happening or not.

Just thinking out loud.

The commands are running but end results are slow - that remains true - correct? Yes. I am receiving the response after delay.

Are the commands being run via some sort of script or macro?
I have created a CPP (C++) application which is posting these commands.

Is it possible to add some commands that display results, actions, etc, that are taking place (or should be taking place) as the commands progress?
from the application side, I have narrowed down to DeviceIoControl API. I am not sure if I can monitor HDD while the execution is progressing. Let me try the links you shared.

 

[fzabkar]

If you want to play with ATA terminal software ...

https://www.hddoracle.com/viewtopic.php?f=22&t=1765

I would use the demo version of WDMarvel.

These tools enable you to directly manipulate the ATA task file registers.

 

[Ralston18]

Agree:

As stated, out of my comfort zone,

However being able to make changes to see what is happens is key to discovering where the problem may be.