[PATCH 1/3] m25p80: Convert to support tracing

[PATCH 1/3] m25p80: Convert to support tracing

[Guenter Roeck]

While at it, add some trace messages to help debug problems
seen when running the latest Linux kernel.

Signed-off-by: Guenter Roeck <linux@roeck-us.net>
---
 hw/block/m25p80.c     | 48 ++++++++++++++++++++-----------------------
 hw/block/trace-events | 16 +++++++++++++++
 2 files changed, 38 insertions(+), 26 deletions(-)

diff --git a/hw/block/m25p80.c b/hw/block/m25p80.c
index 11ff5b9ad7..63e050d7d3 100644
--- a/hw/block/m25p80.c
+++ b/hw/block/m25p80.c
@@ -32,17 +32,7 @@
 #include "qemu/module.h"
 #include "qemu/error-report.h"
 #include "qapi/error.h"
-
-#ifndef M25P80_ERR_DEBUG
-#define M25P80_ERR_DEBUG 0
-#endif
-
-#define DB_PRINT_L(level, ...) do { \
-    if (M25P80_ERR_DEBUG > (level)) { \
-        fprintf(stderr,  ": %s: ", __func__); \
-        fprintf(stderr, ## __VA_ARGS__); \
-    } \
-} while (0)
+#include "trace.h"
 
 /* Fields for FlashPartInfo->flags */
 
@@ -574,7 +564,8 @@ static void flash_erase(Flash *s, int offset, FlashCMD cmd)
         abort();
     }
 
-    DB_PRINT_L(0, "offset = %#x, len = %d\n", offset, len);
+    trace_m25p80_flash_erase(offset, len);
+
     if ((s->pi->flags & capa_to_assert) != capa_to_assert) {
         qemu_log_mask(LOG_GUEST_ERROR, "M25P80: %d erase size not supported by"
                       " device\n", len);
@@ -607,8 +598,7 @@ void flash_write8(Flash *s, uint32_t addr, uint8_t data)
     }
 
     if ((prev ^ data) & data) {
-        DB_PRINT_L(1, "programming zero to one! addr=%" PRIx32 "  %" PRIx8
-                   " -> %" PRIx8 "\n", addr, prev, data);
+        trace_m25p80_programming_zero_to_one(addr, prev, data);
     }
 
     if (s->pi->flags & EEPROM) {
@@ -662,6 +652,9 @@ static void complete_collecting_data(Flash *s)
 
     s->state = STATE_IDLE;
 
+    trace_m25p80_complete_collecting(s->cmd_in_progress, n, s->ear,
+                                     s->cur_addr);
+
     switch (s->cmd_in_progress) {
     case DPP:
     case QPP:
@@ -825,7 +818,7 @@ static void reset_memory(Flash *s)
         break;
     }
 
-    DB_PRINT_L(0, "Reset done.\n");
+    trace_m25p80_reset_done();
 }
 
 static void decode_fast_read_cmd(Flash *s)
@@ -941,9 +934,10 @@ static void decode_qio_read_cmd(Flash *s)
 
 static void decode_new_cmd(Flash *s, uint32_t value)
 {
-    s->cmd_in_progress = value;
     int i;
-    DB_PRINT_L(0, "decoded new command:%x\n", value);
+
+    s->cmd_in_progress = value;
+    trace_m25p80_command_decoded(value);
 
     if (value != RESET_MEMORY) {
         s->reset_enable = false;
@@ -1042,7 +1036,7 @@ static void decode_new_cmd(Flash *s, uint32_t value)
         break;
 
     case JEDEC_READ:
-        DB_PRINT_L(0, "populated jedec code\n");
+        trace_m25p80_populated_jedec();
         for (i = 0; i < s->pi->id_len; i++) {
             s->data[i] = s->pi->id[i];
         }
@@ -1063,7 +1057,7 @@ static void decode_new_cmd(Flash *s, uint32_t value)
     case BULK_ERASE_60:
     case BULK_ERASE:
         if (s->write_enable) {
-            DB_PRINT_L(0, "chip erase\n");
+            trace_m25p80_chip_erase();
             flash_erase(s, 0, BULK_ERASE);
         } else {
             qemu_log_mask(LOG_GUEST_ERROR, "M25P80: chip erase with write "
@@ -1184,7 +1178,7 @@ static int m25p80_cs(SSISlave *ss, bool select)
         s->data_read_loop = false;
     }
 
-    DB_PRINT_L(0, "%sselect\n", select ? "de" : "");
+    trace_m25p80_select(select ? "de" : "");
 
     return 0;
 }
@@ -1194,19 +1188,20 @@ static uint32_t m25p80_transfer8(SSISlave *ss, uint32_t tx)
     Flash *s = M25P80(ss);
     uint32_t r = 0;
 
+    trace_m25p80_transfer(s->state, s->len, s->needed_bytes, s->pos,
+                          s->cur_addr, (uint8_t)tx);
+
     switch (s->state) {
 
     case STATE_PAGE_PROGRAM:
-        DB_PRINT_L(1, "page program cur_addr=%#" PRIx32 " data=%" PRIx8 "\n",
-                   s->cur_addr, (uint8_t)tx);
+        trace_m25p80_page_program(s->cur_addr, (uint8_t)tx);
         flash_write8(s, s->cur_addr, (uint8_t)tx);
         s->cur_addr = (s->cur_addr + 1) & (s->size - 1);
         break;
 
     case STATE_READ:
         r = s->storage[s->cur_addr];
-        DB_PRINT_L(1, "READ 0x%" PRIx32 "=%" PRIx8 "\n", s->cur_addr,
-                   (uint8_t)r);
+        trace_m25p80_read_byte(s->cur_addr, (uint8_t)r);
         s->cur_addr = (s->cur_addr + 1) & (s->size - 1);
         break;
 
@@ -1244,6 +1239,7 @@ static uint32_t m25p80_transfer8(SSISlave *ss, uint32_t tx)
         }
 
         r = s->data[s->pos];
+        trace_m25p80_read_data(s->pos, (uint8_t)r);
         s->pos++;
         if (s->pos == s->len) {
             s->pos = 0;
@@ -1281,7 +1277,7 @@ static void m25p80_realize(SSISlave *ss, Error **errp)
             return;
         }
 
-        DB_PRINT_L(0, "Binding to IF_MTD drive\n");
+        trace_m25p80_binding();
         s->storage = blk_blockalign(s->blk, s->size);
 
         if (blk_pread(s->blk, 0, s->storage, s->size) != s->size) {
@@ -1289,7 +1285,7 @@ static void m25p80_realize(SSISlave *ss, Error **errp)
             return;
         }
     } else {
-        DB_PRINT_L(0, "No BDRV - binding to RAM\n");
+        trace_m25p80_binding_no_bdrv();
         s->storage = blk_blockalign(NULL, s->size);
         memset(s->storage, 0xFF, s->size);
     }
diff --git a/hw/block/trace-events b/hw/block/trace-events
index c03e80c2c9..d052f7578c 100644
--- a/hw/block/trace-events
+++ b/hw/block/trace-events
@@ -134,3 +134,19 @@ xen_block_blockdev_add(char *str) "%s"
 xen_block_blockdev_del(const char *node_name) "%s"
 xen_block_device_create(unsigned int number) "%u"
 xen_block_device_destroy(unsigned int number) "%u"
+
+# m25p80.c
+m25p80_flash_erase(int offset, uint32_t len) "offset = 0x%"PRIx32", len = %u"
+m25p80_programming_zero_to_one(uint32_t addr, uint8_t prev, uint8_t data) "programming zero to one! addr=0x%"PRIx32"  0x%"PRIx8" -> 0x%"PRIx8
+m25p80_reset_done(void) "Reset done."
+m25p80_command_decoded(uint32_t cmd) "new command:0x%"PRIx32
+m25p80_complete_collecting(uint32_t cmd, int n, uint8_t ear, uint32_t cur_addr) "decode cmd: 0x%"PRIx32" len %d ear 0x%"PRIx8" addr 0x%"PRIx32
+m25p80_populated_jedec(void) "populated jedec code"
+m25p80_chip_erase(void) "chip erase"
+m25p80_select(const char *what) "%sselect"
+m25p80_page_program(uint32_t addr, uint8_t tx) "page program cur_addr=0x%"PRIx32" data=0x%"PRIx8
+m25p80_transfer(uint8_t state, uint32_t len, uint8_t needed, uint32_t pos, uint32_t cur_addr, uint8_t t) "Transfer state 0x%"PRIx8" len 0x%"PRIx32" needed 0x%"PRIx8" pos 0x%"PRIx32" addr 0x%"PRIx32" tx 0x%"PRIx8
+m25p80_read_byte(uint32_t addr, uint8_t v) "Read byte 0x%"PRIx32"=0x%"PRIx8
+m25p80_read_data(uint32_t pos, uint8_t v) "Read data 0x%"PRIx32"=0x%"PRIx8
+m25p80_binding(void) "Binding to IF_MTD drive"
+m25p80_binding_no_bdrv(void) "No BDRV - binding to RAM"
-- 
2.17.1

[PATCH 2/3] m25p80: Improve command handling for Jedec and unsupported commands

[Guenter Roeck]

Always report 6 bytes of JEDEC data. Fill remaining data with 0.

For unsupported commands, keep sending a value of 0 until the chip
is deselected.

Both changes avoid attempts to decode random commands. Up to now this
happened if the reported Jedec data was shorter than 6 bytes but the
host read 6 bytes, and with all unsupported commands.

Signed-off-by: Guenter Roeck <linux@roeck-us.net>
---
 hw/block/m25p80.c | 10 +++++++++-
 1 file changed, 9 insertions(+), 1 deletion(-)

diff --git a/hw/block/m25p80.c b/hw/block/m25p80.c
index 63e050d7d3..aca75edcc1 100644
--- a/hw/block/m25p80.c
+++ b/hw/block/m25p80.c
@@ -1040,8 +1040,11 @@ static void decode_new_cmd(Flash *s, uint32_t value)
         for (i = 0; i < s->pi->id_len; i++) {
             s->data[i] = s->pi->id[i];
         }
+        for (; i < SPI_NOR_MAX_ID_LEN; i++) {
+            s->data[i] = 0;
+        }
 
-        s->len = s->pi->id_len;
+        s->len = SPI_NOR_MAX_ID_LEN;
         s->pos = 0;
         s->state = STATE_READING_DATA;
         break;
@@ -1158,6 +1161,11 @@ static void decode_new_cmd(Flash *s, uint32_t value)
         s->quad_enable = false;
         break;
     default:
+        s->pos = 0;
+        s->len = 1;
+        s->state = STATE_READING_DATA;
+        s->data_read_loop = true;
+        s->data[0] = 0;
         qemu_log_mask(LOG_GUEST_ERROR, "M25P80: Unknown cmd %x\n", value);
         break;
     }
-- 
2.17.1

[PATCH 3/3] aspeed/smc: Fix number of dummy cycles for FAST_READ_4 command

[Guenter Roeck]

The Linux kernel recently started using FAST_READ_4 commands.
This results in flash read failures. At the same time, the m25p80
emulation is seen to read 8 more bytes than expected. Adjusting the
expected number of dummy cycles to match FAST_READ fixes the problem.

Signed-off-by: Guenter Roeck <linux@roeck-us.net>
---
 hw/ssi/aspeed_smc.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/hw/ssi/aspeed_smc.c b/hw/ssi/aspeed_smc.c
index f0c7bbbad3..61e8fa57d3 100644
--- a/hw/ssi/aspeed_smc.c
+++ b/hw/ssi/aspeed_smc.c
@@ -762,11 +762,11 @@ static int aspeed_smc_num_dummies(uint8_t command)
     case FAST_READ:
     case DOR:
     case QOR:
+    case FAST_READ_4:
     case DOR_4:
     case QOR_4:
         return 1;
     case DIOR:
-    case FAST_READ_4:
     case DIOR_4:
         return 2;
     case QIOR:
-- 
2.17.1

Re: [PATCH 1/3] m25p80: Convert to support tracing

[Alistair Francis]

On Mon, Feb 3, 2020 at 10:10 AM Guenter Roeck <linux@roeck-us.net> wrote:
>
> While at it, add some trace messages to help debug problems
> seen when running the latest Linux kernel.
>
> Signed-off-by: Guenter Roeck <linux@roeck-us.net>

Reviewed-by: Alistair Francis <alistair.francis@wdc.com>

Alistair

> ---
>  hw/block/m25p80.c     | 48 ++++++++++++++++++++-----------------------
>  hw/block/trace-events | 16 +++++++++++++++
>  2 files changed, 38 insertions(+), 26 deletions(-)
>
> diff --git a/hw/block/m25p80.c b/hw/block/m25p80.c
> index 11ff5b9ad7..63e050d7d3 100644
> --- a/hw/block/m25p80.c
> +++ b/hw/block/m25p80.c
> @@ -32,17 +32,7 @@
>  #include "qemu/module.h"
>  #include "qemu/error-report.h"
>  #include "qapi/error.h"
> -
> -#ifndef M25P80_ERR_DEBUG
> -#define M25P80_ERR_DEBUG 0
> -#endif
> -
> -#define DB_PRINT_L(level, ...) do { \
> -    if (M25P80_ERR_DEBUG > (level)) { \
> -        fprintf(stderr,  ": %s: ", __func__); \
> -        fprintf(stderr, ## __VA_ARGS__); \
> -    } \
> -} while (0)
> +#include "trace.h"
>
>  /* Fields for FlashPartInfo->flags */
>
> @@ -574,7 +564,8 @@ static void flash_erase(Flash *s, int offset, FlashCMD cmd)
>          abort();
>      }
>
> -    DB_PRINT_L(0, "offset = %#x, len = %d\n", offset, len);
> +    trace_m25p80_flash_erase(offset, len);
> +
>      if ((s->pi->flags & capa_to_assert) != capa_to_assert) {
>          qemu_log_mask(LOG_GUEST_ERROR, "M25P80: %d erase size not supported by"
>                        " device\n", len);
> @@ -607,8 +598,7 @@ void flash_write8(Flash *s, uint32_t addr, uint8_t data)
>      }
>
>      if ((prev ^ data) & data) {
> -        DB_PRINT_L(1, "programming zero to one! addr=%" PRIx32 "  %" PRIx8
> -                   " -> %" PRIx8 "\n", addr, prev, data);
> +        trace_m25p80_programming_zero_to_one(addr, prev, data);
>      }
>
>      if (s->pi->flags & EEPROM) {
> @@ -662,6 +652,9 @@ static void complete_collecting_data(Flash *s)
>
>      s->state = STATE_IDLE;
>
> +    trace_m25p80_complete_collecting(s->cmd_in_progress, n, s->ear,
> +                                     s->cur_addr);
> +
>      switch (s->cmd_in_progress) {
>      case DPP:
>      case QPP:
> @@ -825,7 +818,7 @@ static void reset_memory(Flash *s)
>          break;
>      }
>
> -    DB_PRINT_L(0, "Reset done.\n");
> +    trace_m25p80_reset_done();
>  }
>
>  static void decode_fast_read_cmd(Flash *s)
> @@ -941,9 +934,10 @@ static void decode_qio_read_cmd(Flash *s)
>
>  static void decode_new_cmd(Flash *s, uint32_t value)
>  {
> -    s->cmd_in_progress = value;
>      int i;
> -    DB_PRINT_L(0, "decoded new command:%x\n", value);
> +
> +    s->cmd_in_progress = value;
> +    trace_m25p80_command_decoded(value);
>
>      if (value != RESET_MEMORY) {
>          s->reset_enable = false;
> @@ -1042,7 +1036,7 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>          break;
>
>      case JEDEC_READ:
> -        DB_PRINT_L(0, "populated jedec code\n");
> +        trace_m25p80_populated_jedec();
>          for (i = 0; i < s->pi->id_len; i++) {
>              s->data[i] = s->pi->id[i];
>          }
> @@ -1063,7 +1057,7 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>      case BULK_ERASE_60:
>      case BULK_ERASE:
>          if (s->write_enable) {
> -            DB_PRINT_L(0, "chip erase\n");
> +            trace_m25p80_chip_erase();
>              flash_erase(s, 0, BULK_ERASE);
>          } else {
>              qemu_log_mask(LOG_GUEST_ERROR, "M25P80: chip erase with write "
> @@ -1184,7 +1178,7 @@ static int m25p80_cs(SSISlave *ss, bool select)
>          s->data_read_loop = false;
>      }
>
> -    DB_PRINT_L(0, "%sselect\n", select ? "de" : "");
> +    trace_m25p80_select(select ? "de" : "");
>
>      return 0;
>  }
> @@ -1194,19 +1188,20 @@ static uint32_t m25p80_transfer8(SSISlave *ss, uint32_t tx)
>      Flash *s = M25P80(ss);
>      uint32_t r = 0;
>
> +    trace_m25p80_transfer(s->state, s->len, s->needed_bytes, s->pos,
> +                          s->cur_addr, (uint8_t)tx);
> +
>      switch (s->state) {
>
>      case STATE_PAGE_PROGRAM:
> -        DB_PRINT_L(1, "page program cur_addr=%#" PRIx32 " data=%" PRIx8 "\n",
> -                   s->cur_addr, (uint8_t)tx);
> +        trace_m25p80_page_program(s->cur_addr, (uint8_t)tx);
>          flash_write8(s, s->cur_addr, (uint8_t)tx);
>          s->cur_addr = (s->cur_addr + 1) & (s->size - 1);
>          break;
>
>      case STATE_READ:
>          r = s->storage[s->cur_addr];
> -        DB_PRINT_L(1, "READ 0x%" PRIx32 "=%" PRIx8 "\n", s->cur_addr,
> -                   (uint8_t)r);
> +        trace_m25p80_read_byte(s->cur_addr, (uint8_t)r);
>          s->cur_addr = (s->cur_addr + 1) & (s->size - 1);
>          break;
>
> @@ -1244,6 +1239,7 @@ static uint32_t m25p80_transfer8(SSISlave *ss, uint32_t tx)
>          }
>
>          r = s->data[s->pos];
> +        trace_m25p80_read_data(s->pos, (uint8_t)r);
>          s->pos++;
>          if (s->pos == s->len) {
>              s->pos = 0;
> @@ -1281,7 +1277,7 @@ static void m25p80_realize(SSISlave *ss, Error **errp)
>              return;
>          }
>
> -        DB_PRINT_L(0, "Binding to IF_MTD drive\n");
> +        trace_m25p80_binding();
>          s->storage = blk_blockalign(s->blk, s->size);
>
>          if (blk_pread(s->blk, 0, s->storage, s->size) != s->size) {
> @@ -1289,7 +1285,7 @@ static void m25p80_realize(SSISlave *ss, Error **errp)
>              return;
>          }
>      } else {
> -        DB_PRINT_L(0, "No BDRV - binding to RAM\n");
> +        trace_m25p80_binding_no_bdrv();
>          s->storage = blk_blockalign(NULL, s->size);
>          memset(s->storage, 0xFF, s->size);
>      }
> diff --git a/hw/block/trace-events b/hw/block/trace-events
> index c03e80c2c9..d052f7578c 100644
> --- a/hw/block/trace-events
> +++ b/hw/block/trace-events
> @@ -134,3 +134,19 @@ xen_block_blockdev_add(char *str) "%s"
>  xen_block_blockdev_del(const char *node_name) "%s"
>  xen_block_device_create(unsigned int number) "%u"
>  xen_block_device_destroy(unsigned int number) "%u"
> +
> +# m25p80.c
> +m25p80_flash_erase(int offset, uint32_t len) "offset = 0x%"PRIx32", len = %u"
> +m25p80_programming_zero_to_one(uint32_t addr, uint8_t prev, uint8_t data) "programming zero to one! addr=0x%"PRIx32"  0x%"PRIx8" -> 0x%"PRIx8
> +m25p80_reset_done(void) "Reset done."
> +m25p80_command_decoded(uint32_t cmd) "new command:0x%"PRIx32
> +m25p80_complete_collecting(uint32_t cmd, int n, uint8_t ear, uint32_t cur_addr) "decode cmd: 0x%"PRIx32" len %d ear 0x%"PRIx8" addr 0x%"PRIx32
> +m25p80_populated_jedec(void) "populated jedec code"
> +m25p80_chip_erase(void) "chip erase"
> +m25p80_select(const char *what) "%sselect"
> +m25p80_page_program(uint32_t addr, uint8_t tx) "page program cur_addr=0x%"PRIx32" data=0x%"PRIx8
> +m25p80_transfer(uint8_t state, uint32_t len, uint8_t needed, uint32_t pos, uint32_t cur_addr, uint8_t t) "Transfer state 0x%"PRIx8" len 0x%"PRIx32" needed 0x%"PRIx8" pos 0x%"PRIx32" addr 0x%"PRIx32" tx 0x%"PRIx8
> +m25p80_read_byte(uint32_t addr, uint8_t v) "Read byte 0x%"PRIx32"=0x%"PRIx8
> +m25p80_read_data(uint32_t pos, uint8_t v) "Read data 0x%"PRIx32"=0x%"PRIx8
> +m25p80_binding(void) "Binding to IF_MTD drive"
> +m25p80_binding_no_bdrv(void) "No BDRV - binding to RAM"
> --
> 2.17.1
>
>

Re: [PATCH 1/3] m25p80: Convert to support tracing

[Cédric Le Goater]

On 2/3/20 7:09 PM, Guenter Roeck wrote:
> While at it, add some trace messages to help debug problems
> seen when running the latest Linux kernel.
> 
> Signed-off-by: Guenter Roeck <linux@roeck-us.net>


Reviewed-by: Cédric Le Goater <clg@kaod.org>

We have been chasing a bug for years on the witherspoon-bmc machine 
using UBIfs. It will be useful. 

What kind of issue are you looking at ? 

Thanks,

C. 

> ---
>  hw/block/m25p80.c     | 48 ++++++++++++++++++++-----------------------
>  hw/block/trace-events | 16 +++++++++++++++
>  2 files changed, 38 insertions(+), 26 deletions(-)
> 
> diff --git a/hw/block/m25p80.c b/hw/block/m25p80.c
> index 11ff5b9ad7..63e050d7d3 100644
> --- a/hw/block/m25p80.c
> +++ b/hw/block/m25p80.c
> @@ -32,17 +32,7 @@
>  #include "qemu/module.h"
>  #include "qemu/error-report.h"
>  #include "qapi/error.h"
> -
> -#ifndef M25P80_ERR_DEBUG
> -#define M25P80_ERR_DEBUG 0
> -#endif
> -
> -#define DB_PRINT_L(level, ...) do { \
> -    if (M25P80_ERR_DEBUG > (level)) { \
> -        fprintf(stderr,  ": %s: ", __func__); \
> -        fprintf(stderr, ## __VA_ARGS__); \
> -    } \
> -} while (0)
> +#include "trace.h"
>  
>  /* Fields for FlashPartInfo->flags */
>  
> @@ -574,7 +564,8 @@ static void flash_erase(Flash *s, int offset, FlashCMD cmd)
>          abort();
>      }
>  
> -    DB_PRINT_L(0, "offset = %#x, len = %d\n", offset, len);
> +    trace_m25p80_flash_erase(offset, len);
> +
>      if ((s->pi->flags & capa_to_assert) != capa_to_assert) {
>          qemu_log_mask(LOG_GUEST_ERROR, "M25P80: %d erase size not supported by"
>                        " device\n", len);
> @@ -607,8 +598,7 @@ void flash_write8(Flash *s, uint32_t addr, uint8_t data)
>      }
>  
>      if ((prev ^ data) & data) {
> -        DB_PRINT_L(1, "programming zero to one! addr=%" PRIx32 "  %" PRIx8
> -                   " -> %" PRIx8 "\n", addr, prev, data);
> +        trace_m25p80_programming_zero_to_one(addr, prev, data);
>      }
>  
>      if (s->pi->flags & EEPROM) {
> @@ -662,6 +652,9 @@ static void complete_collecting_data(Flash *s)
>  
>      s->state = STATE_IDLE;
>  
> +    trace_m25p80_complete_collecting(s->cmd_in_progress, n, s->ear,
> +                                     s->cur_addr);
> +
>      switch (s->cmd_in_progress) {
>      case DPP:
>      case QPP:
> @@ -825,7 +818,7 @@ static void reset_memory(Flash *s)
>          break;
>      }
>  
> -    DB_PRINT_L(0, "Reset done.\n");
> +    trace_m25p80_reset_done();
>  }
>  
>  static void decode_fast_read_cmd(Flash *s)
> @@ -941,9 +934,10 @@ static void decode_qio_read_cmd(Flash *s)
>  
>  static void decode_new_cmd(Flash *s, uint32_t value)
>  {
> -    s->cmd_in_progress = value;
>      int i;
> -    DB_PRINT_L(0, "decoded new command:%x\n", value);
> +
> +    s->cmd_in_progress = value;
> +    trace_m25p80_command_decoded(value);
>  
>      if (value != RESET_MEMORY) {
>          s->reset_enable = false;
> @@ -1042,7 +1036,7 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>          break;
>  
>      case JEDEC_READ:
> -        DB_PRINT_L(0, "populated jedec code\n");
> +        trace_m25p80_populated_jedec();
>          for (i = 0; i < s->pi->id_len; i++) {
>              s->data[i] = s->pi->id[i];
>          }
> @@ -1063,7 +1057,7 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>      case BULK_ERASE_60:
>      case BULK_ERASE:
>          if (s->write_enable) {
> -            DB_PRINT_L(0, "chip erase\n");
> +            trace_m25p80_chip_erase();
>              flash_erase(s, 0, BULK_ERASE);
>          } else {
>              qemu_log_mask(LOG_GUEST_ERROR, "M25P80: chip erase with write "
> @@ -1184,7 +1178,7 @@ static int m25p80_cs(SSISlave *ss, bool select)
>          s->data_read_loop = false;
>      }
>  
> -    DB_PRINT_L(0, "%sselect\n", select ? "de" : "");
> +    trace_m25p80_select(select ? "de" : "");
>  
>      return 0;
>  }
> @@ -1194,19 +1188,20 @@ static uint32_t m25p80_transfer8(SSISlave *ss, uint32_t tx)
>      Flash *s = M25P80(ss);
>      uint32_t r = 0;
>  
> +    trace_m25p80_transfer(s->state, s->len, s->needed_bytes, s->pos,
> +                          s->cur_addr, (uint8_t)tx);
> +
>      switch (s->state) {
>  
>      case STATE_PAGE_PROGRAM:
> -        DB_PRINT_L(1, "page program cur_addr=%#" PRIx32 " data=%" PRIx8 "\n",
> -                   s->cur_addr, (uint8_t)tx);
> +        trace_m25p80_page_program(s->cur_addr, (uint8_t)tx);
>          flash_write8(s, s->cur_addr, (uint8_t)tx);
>          s->cur_addr = (s->cur_addr + 1) & (s->size - 1);
>          break;
>  
>      case STATE_READ:
>          r = s->storage[s->cur_addr];
> -        DB_PRINT_L(1, "READ 0x%" PRIx32 "=%" PRIx8 "\n", s->cur_addr,
> -                   (uint8_t)r);
> +        trace_m25p80_read_byte(s->cur_addr, (uint8_t)r);
>          s->cur_addr = (s->cur_addr + 1) & (s->size - 1);
>          break;
>  
> @@ -1244,6 +1239,7 @@ static uint32_t m25p80_transfer8(SSISlave *ss, uint32_t tx)
>          }
>  
>          r = s->data[s->pos];
> +        trace_m25p80_read_data(s->pos, (uint8_t)r);
>          s->pos++;
>          if (s->pos == s->len) {
>              s->pos = 0;
> @@ -1281,7 +1277,7 @@ static void m25p80_realize(SSISlave *ss, Error **errp)
>              return;
>          }
>  
> -        DB_PRINT_L(0, "Binding to IF_MTD drive\n");
> +        trace_m25p80_binding();
>          s->storage = blk_blockalign(s->blk, s->size);
>  
>          if (blk_pread(s->blk, 0, s->storage, s->size) != s->size) {
> @@ -1289,7 +1285,7 @@ static void m25p80_realize(SSISlave *ss, Error **errp)
>              return;
>          }
>      } else {
> -        DB_PRINT_L(0, "No BDRV - binding to RAM\n");
> +        trace_m25p80_binding_no_bdrv();
>          s->storage = blk_blockalign(NULL, s->size);
>          memset(s->storage, 0xFF, s->size);
>      }
> diff --git a/hw/block/trace-events b/hw/block/trace-events
> index c03e80c2c9..d052f7578c 100644
> --- a/hw/block/trace-events
> +++ b/hw/block/trace-events
> @@ -134,3 +134,19 @@ xen_block_blockdev_add(char *str) "%s"
>  xen_block_blockdev_del(const char *node_name) "%s"
>  xen_block_device_create(unsigned int number) "%u"
>  xen_block_device_destroy(unsigned int number) "%u"
> +
> +# m25p80.c
> +m25p80_flash_erase(int offset, uint32_t len) "offset = 0x%"PRIx32", len = %u"
> +m25p80_programming_zero_to_one(uint32_t addr, uint8_t prev, uint8_t data) "programming zero to one! addr=0x%"PRIx32"  0x%"PRIx8" -> 0x%"PRIx8
> +m25p80_reset_done(void) "Reset done."
> +m25p80_command_decoded(uint32_t cmd) "new command:0x%"PRIx32
> +m25p80_complete_collecting(uint32_t cmd, int n, uint8_t ear, uint32_t cur_addr) "decode cmd: 0x%"PRIx32" len %d ear 0x%"PRIx8" addr 0x%"PRIx32
> +m25p80_populated_jedec(void) "populated jedec code"
> +m25p80_chip_erase(void) "chip erase"
> +m25p80_select(const char *what) "%sselect"
> +m25p80_page_program(uint32_t addr, uint8_t tx) "page program cur_addr=0x%"PRIx32" data=0x%"PRIx8
> +m25p80_transfer(uint8_t state, uint32_t len, uint8_t needed, uint32_t pos, uint32_t cur_addr, uint8_t t) "Transfer state 0x%"PRIx8" len 0x%"PRIx32" needed 0x%"PRIx8" pos 0x%"PRIx32" addr 0x%"PRIx32" tx 0x%"PRIx8
> +m25p80_read_byte(uint32_t addr, uint8_t v) "Read byte 0x%"PRIx32"=0x%"PRIx8
> +m25p80_read_data(uint32_t pos, uint8_t v) "Read data 0x%"PRIx32"=0x%"PRIx8
> +m25p80_binding(void) "Binding to IF_MTD drive"
> +m25p80_binding_no_bdrv(void) "No BDRV - binding to RAM"
> 

Re: [PATCH 3/3] aspeed/smc: Fix number of dummy cycles for FAST_READ_4 command

[Cédric Le Goater]

On 2/3/20 7:09 PM, Guenter Roeck wrote:
> The Linux kernel recently started using FAST_READ_4 commands.
> This results in flash read failures. At the same time, the m25p80
> emulation is seen to read 8 more bytes than expected. Adjusting the
> expected number of dummy cycles to match FAST_READ fixes the problem.

Which machine are you using for these tests ? the AST2500 evb using
the w25q256 flash model ? 

Any how, it looks correct. 

Reviewed-by: Cédric Le Goater <clg@kaod.org>
Fixes: f95c4bffdc4c ("aspeed/smc: snoop SPI transfers to fake dummy cycles")

I think commit ef06ca3946e2 ("xilinx_spips: Add support for RX discard 
and RX drain") needs a similar fix. Adding Francisco.

Thanks,

C. 


> Signed-off-by: Guenter Roeck <linux@roeck-us.net>
> ---
>  hw/ssi/aspeed_smc.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/hw/ssi/aspeed_smc.c b/hw/ssi/aspeed_smc.c
> index f0c7bbbad3..61e8fa57d3 100644
> --- a/hw/ssi/aspeed_smc.c
> +++ b/hw/ssi/aspeed_smc.c
> @@ -762,11 +762,11 @@ static int aspeed_smc_num_dummies(uint8_t command)
>      case FAST_READ:
>      case DOR:
>      case QOR:
> +    case FAST_READ_4:
>      case DOR_4:
>      case QOR_4:
>          return 1;
>      case DIOR:
> -    case FAST_READ_4:
>      case DIOR_4:
>          return 2;
>      case QIOR:
> 

Re: [PATCH 2/3] m25p80: Improve command handling for Jedec and unsupported commands

[Cédric Le Goater]

On 2/3/20 7:09 PM, Guenter Roeck wrote:
> Always report 6 bytes of JEDEC data. Fill remaining data with 0.
> 
> For unsupported commands, keep sending a value of 0 until the chip
> is deselected.
> 
> Both changes avoid attempts to decode random commands. Up to now this
> happened if the reported Jedec data was shorter than 6 bytes but the
> host read 6 bytes, and with all unsupported commands.

Do you have a concrete example for that ? machine and flash model.

> Signed-off-by: Guenter Roeck <linux@roeck-us.net>
> ---
>  hw/block/m25p80.c | 10 +++++++++-
>  1 file changed, 9 insertions(+), 1 deletion(-)
> 
> diff --git a/hw/block/m25p80.c b/hw/block/m25p80.c
> index 63e050d7d3..aca75edcc1 100644
> --- a/hw/block/m25p80.c
> +++ b/hw/block/m25p80.c
> @@ -1040,8 +1040,11 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>          for (i = 0; i < s->pi->id_len; i++) {
>              s->data[i] = s->pi->id[i];
>          }
> +        for (; i < SPI_NOR_MAX_ID_LEN; i++) {
> +            s->data[i] = 0;
> +        }

It seems that data should be reseted in m25p80_cs() also.

>  
> -        s->len = s->pi->id_len;
> +        s->len = SPI_NOR_MAX_ID_LEN;
>          s->pos = 0;
>          s->state = STATE_READING_DATA;
>          break;
> @@ -1158,6 +1161,11 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>          s->quad_enable = false;
>          break;
>      default:
> +        s->pos = 0;
> +        s->len = 1;
> +        s->state = STATE_READING_DATA;
> +        s->data_read_loop = true;
> +        s->data[0] = 0;
>          qemu_log_mask(LOG_GUEST_ERROR, "M25P80: Unknown cmd %x\n", value);
>          break;
>      }
> 

Re: [PATCH 1/3] m25p80: Convert to support tracing

[Philippe Mathieu-Daudé]

On 2/3/20 7:09 PM, Guenter Roeck wrote:
> While at it, add some trace messages to help debug problems
> seen when running the latest Linux kernel.
> 
> Signed-off-by: Guenter Roeck <linux@roeck-us.net>
> ---
>   hw/block/m25p80.c     | 48 ++++++++++++++++++++-----------------------
>   hw/block/trace-events | 16 +++++++++++++++
>   2 files changed, 38 insertions(+), 26 deletions(-)
> 
> diff --git a/hw/block/m25p80.c b/hw/block/m25p80.c
> index 11ff5b9ad7..63e050d7d3 100644
> --- a/hw/block/m25p80.c
> +++ b/hw/block/m25p80.c
> @@ -32,17 +32,7 @@
>   #include "qemu/module.h"
>   #include "qemu/error-report.h"
>   #include "qapi/error.h"
> -
> -#ifndef M25P80_ERR_DEBUG
> -#define M25P80_ERR_DEBUG 0
> -#endif
> -
> -#define DB_PRINT_L(level, ...) do { \
> -    if (M25P80_ERR_DEBUG > (level)) { \
> -        fprintf(stderr,  ": %s: ", __func__); \
> -        fprintf(stderr, ## __VA_ARGS__); \
> -    } \
> -} while (0)
> +#include "trace.h"
>   
>   /* Fields for FlashPartInfo->flags */
>   
> @@ -574,7 +564,8 @@ static void flash_erase(Flash *s, int offset, FlashCMD cmd)
>           abort();
>       }
>   
> -    DB_PRINT_L(0, "offset = %#x, len = %d\n", offset, len);
> +    trace_m25p80_flash_erase(offset, len);
> +
>       if ((s->pi->flags & capa_to_assert) != capa_to_assert) {
>           qemu_log_mask(LOG_GUEST_ERROR, "M25P80: %d erase size not supported by"
>                         " device\n", len);
> @@ -607,8 +598,7 @@ void flash_write8(Flash *s, uint32_t addr, uint8_t data)
>       }
>   
>       if ((prev ^ data) & data) {
> -        DB_PRINT_L(1, "programming zero to one! addr=%" PRIx32 "  %" PRIx8
> -                   " -> %" PRIx8 "\n", addr, prev, data);
> +        trace_m25p80_programming_zero_to_one(addr, prev, data);
>       }
>   
>       if (s->pi->flags & EEPROM) {
> @@ -662,6 +652,9 @@ static void complete_collecting_data(Flash *s)
>   
>       s->state = STATE_IDLE;
>   
> +    trace_m25p80_complete_collecting(s->cmd_in_progress, n, s->ear,
> +                                     s->cur_addr);
> +
>       switch (s->cmd_in_progress) {
>       case DPP:
>       case QPP:
> @@ -825,7 +818,7 @@ static void reset_memory(Flash *s)
>           break;
>       }
>   
> -    DB_PRINT_L(0, "Reset done.\n");
> +    trace_m25p80_reset_done();
>   }
>   
>   static void decode_fast_read_cmd(Flash *s)
> @@ -941,9 +934,10 @@ static void decode_qio_read_cmd(Flash *s)
>   
>   static void decode_new_cmd(Flash *s, uint32_t value)
>   {
> -    s->cmd_in_progress = value;
>       int i;
> -    DB_PRINT_L(0, "decoded new command:%x\n", value);
> +
> +    s->cmd_in_progress = value;
> +    trace_m25p80_command_decoded(value);
>   
>       if (value != RESET_MEMORY) {
>           s->reset_enable = false;
> @@ -1042,7 +1036,7 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>           break;
>   
>       case JEDEC_READ:
> -        DB_PRINT_L(0, "populated jedec code\n");
> +        trace_m25p80_populated_jedec();
>           for (i = 0; i < s->pi->id_len; i++) {
>               s->data[i] = s->pi->id[i];
>           }
> @@ -1063,7 +1057,7 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>       case BULK_ERASE_60:
>       case BULK_ERASE:
>           if (s->write_enable) {
> -            DB_PRINT_L(0, "chip erase\n");
> +            trace_m25p80_chip_erase();
>               flash_erase(s, 0, BULK_ERASE);
>           } else {
>               qemu_log_mask(LOG_GUEST_ERROR, "M25P80: chip erase with write "
> @@ -1184,7 +1178,7 @@ static int m25p80_cs(SSISlave *ss, bool select)
>           s->data_read_loop = false;
>       }
>   
> -    DB_PRINT_L(0, "%sselect\n", select ? "de" : "");
> +    trace_m25p80_select(select ? "de" : "");
>   
>       return 0;
>   }
> @@ -1194,19 +1188,20 @@ static uint32_t m25p80_transfer8(SSISlave *ss, uint32_t tx)
>       Flash *s = M25P80(ss);
>       uint32_t r = 0;
>   
> +    trace_m25p80_transfer(s->state, s->len, s->needed_bytes, s->pos,
> +                          s->cur_addr, (uint8_t)tx);
> +
>       switch (s->state) {
>   
>       case STATE_PAGE_PROGRAM:
> -        DB_PRINT_L(1, "page program cur_addr=%#" PRIx32 " data=%" PRIx8 "\n",
> -                   s->cur_addr, (uint8_t)tx);
> +        trace_m25p80_page_program(s->cur_addr, (uint8_t)tx);
>           flash_write8(s, s->cur_addr, (uint8_t)tx);
>           s->cur_addr = (s->cur_addr + 1) & (s->size - 1);
>           break;
>   
>       case STATE_READ:
>           r = s->storage[s->cur_addr];
> -        DB_PRINT_L(1, "READ 0x%" PRIx32 "=%" PRIx8 "\n", s->cur_addr,
> -                   (uint8_t)r);
> +        trace_m25p80_read_byte(s->cur_addr, (uint8_t)r);
>           s->cur_addr = (s->cur_addr + 1) & (s->size - 1);
>           break;
>   
> @@ -1244,6 +1239,7 @@ static uint32_t m25p80_transfer8(SSISlave *ss, uint32_t tx)
>           }
>   
>           r = s->data[s->pos];
> +        trace_m25p80_read_data(s->pos, (uint8_t)r);
>           s->pos++;
>           if (s->pos == s->len) {
>               s->pos = 0;
> @@ -1281,7 +1277,7 @@ static void m25p80_realize(SSISlave *ss, Error **errp)
>               return;
>           }
>   
> -        DB_PRINT_L(0, "Binding to IF_MTD drive\n");
> +        trace_m25p80_binding();
>           s->storage = blk_blockalign(s->blk, s->size);
>   
>           if (blk_pread(s->blk, 0, s->storage, s->size) != s->size) {
> @@ -1289,7 +1285,7 @@ static void m25p80_realize(SSISlave *ss, Error **errp)
>               return;
>           }
>       } else {
> -        DB_PRINT_L(0, "No BDRV - binding to RAM\n");
> +        trace_m25p80_binding_no_bdrv();
>           s->storage = blk_blockalign(NULL, s->size);
>           memset(s->storage, 0xFF, s->size);
>       }
> diff --git a/hw/block/trace-events b/hw/block/trace-events
> index c03e80c2c9..d052f7578c 100644
> --- a/hw/block/trace-events
> +++ b/hw/block/trace-events
> @@ -134,3 +134,19 @@ xen_block_blockdev_add(char *str) "%s"
>   xen_block_blockdev_del(const char *node_name) "%s"
>   xen_block_device_create(unsigned int number) "%u"
>   xen_block_device_destroy(unsigned int number) "%u"
> +
> +# m25p80.c
> +m25p80_flash_erase(int offset, uint32_t len) "offset = 0x%"PRIx32", len = %u"
> +m25p80_programming_zero_to_one(uint32_t addr, uint8_t prev, uint8_t data) "programming zero to one! addr=0x%"PRIx32"  0x%"PRIx8" -> 0x%"PRIx8
> +m25p80_reset_done(void) "Reset done."
> +m25p80_command_decoded(uint32_t cmd) "new command:0x%"PRIx32
> +m25p80_complete_collecting(uint32_t cmd, int n, uint8_t ear, uint32_t cur_addr) "decode cmd: 0x%"PRIx32" len %d ear 0x%"PRIx8" addr 0x%"PRIx32
> +m25p80_populated_jedec(void) "populated jedec code"
> +m25p80_chip_erase(void) "chip erase"
> +m25p80_select(const char *what) "%sselect"
> +m25p80_page_program(uint32_t addr, uint8_t tx) "page program cur_addr=0x%"PRIx32" data=0x%"PRIx8
> +m25p80_transfer(uint8_t state, uint32_t len, uint8_t needed, uint32_t pos, uint32_t cur_addr, uint8_t t) "Transfer state 0x%"PRIx8" len 0x%"PRIx32" needed 0x%"PRIx8" pos 0x%"PRIx32" addr 0x%"PRIx32" tx 0x%"PRIx8
> +m25p80_read_byte(uint32_t addr, uint8_t v) "Read byte 0x%"PRIx32"=0x%"PRIx8
> +m25p80_read_data(uint32_t pos, uint8_t v) "Read data 0x%"PRIx32"=0x%"PRIx8
> +m25p80_binding(void) "Binding to IF_MTD drive"
> +m25p80_binding_no_bdrv(void) "No BDRV - binding to RAM"
> 

Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>

Re: [PATCH 2/3] m25p80: Improve command handling for Jedec and unsupported commands

[Philippe Mathieu-Daudé]

Hi Guenter,

On 2/3/20 7:09 PM, Guenter Roeck wrote:
> Always report 6 bytes of JEDEC data. Fill remaining data with 0.
> 
> For unsupported commands, keep sending a value of 0 until the chip
> is deselected.

Two changes, I'd rather see 2 patches. If you happen to respin they are 
welcome. As the split is trivial maybe a block maintainer is OK to do 
it. Regardless the outcome:
Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>

> 
> Both changes avoid attempts to decode random commands. Up to now this
> happened if the reported Jedec data was shorter than 6 bytes but the
> host read 6 bytes, and with all unsupported commands.
> 
> Signed-off-by: Guenter Roeck <linux@roeck-us.net>
> ---
>   hw/block/m25p80.c | 10 +++++++++-
>   1 file changed, 9 insertions(+), 1 deletion(-)
> 
> diff --git a/hw/block/m25p80.c b/hw/block/m25p80.c
> index 63e050d7d3..aca75edcc1 100644
> --- a/hw/block/m25p80.c
> +++ b/hw/block/m25p80.c
> @@ -1040,8 +1040,11 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>           for (i = 0; i < s->pi->id_len; i++) {
>               s->data[i] = s->pi->id[i];
>           }
> +        for (; i < SPI_NOR_MAX_ID_LEN; i++) {
> +            s->data[i] = 0;
> +        }
>   
> -        s->len = s->pi->id_len;
> +        s->len = SPI_NOR_MAX_ID_LEN;
>           s->pos = 0;
>           s->state = STATE_READING_DATA;
>           break;
> @@ -1158,6 +1161,11 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>           s->quad_enable = false;
>           break;
>       default:
> +        s->pos = 0;
> +        s->len = 1;
> +        s->state = STATE_READING_DATA;
> +        s->data_read_loop = true;
> +        s->data[0] = 0;
>           qemu_log_mask(LOG_GUEST_ERROR, "M25P80: Unknown cmd %x\n", value);
>           break;
>       }
> 

Re: [PATCH 2/3] m25p80: Improve command handling for Jedec and unsupported commands

[Philippe Mathieu-Daudé]

On 2/4/20 9:53 AM, Cédric Le Goater wrote:
> On 2/3/20 7:09 PM, Guenter Roeck wrote:
>> Always report 6 bytes of JEDEC data. Fill remaining data with 0.
>>
>> For unsupported commands, keep sending a value of 0 until the chip
>> is deselected.
>>
>> Both changes avoid attempts to decode random commands. Up to now this
>> happened if the reported Jedec data was shorter than 6 bytes but the
>> host read 6 bytes, and with all unsupported commands.
> 
> Do you have a concrete example for that ? machine and flash model.
> 
>> Signed-off-by: Guenter Roeck <linux@roeck-us.net>
>> ---
>>   hw/block/m25p80.c | 10 +++++++++-
>>   1 file changed, 9 insertions(+), 1 deletion(-)
>>
>> diff --git a/hw/block/m25p80.c b/hw/block/m25p80.c
>> index 63e050d7d3..aca75edcc1 100644
>> --- a/hw/block/m25p80.c
>> +++ b/hw/block/m25p80.c
>> @@ -1040,8 +1040,11 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>>           for (i = 0; i < s->pi->id_len; i++) {
>>               s->data[i] = s->pi->id[i];
>>           }
>> +        for (; i < SPI_NOR_MAX_ID_LEN; i++) {
>> +            s->data[i] = 0;
>> +        }
> 
> It seems that data should be reseted in m25p80_cs() also.

I am not sure, since a guest can queue various requests in a single 
frame. Guenter patch seems correct to me.

All the others uses in decode_new_cmd() fill data[] up to the correct 
length, so are safe.

In complete_collecting_data() the access to data[] should be protected 
by STATE_COLLECTING_VAR_LEN_DATA (state only changes when enough data).

>>   
>> -        s->len = s->pi->id_len;
>> +        s->len = SPI_NOR_MAX_ID_LEN;
>>           s->pos = 0;
>>           s->state = STATE_READING_DATA;
>>           break;
>> @@ -1158,6 +1161,11 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>>           s->quad_enable = false;
>>           break;
>>       default:
>> +        s->pos = 0;
>> +        s->len = 1;
>> +        s->state = STATE_READING_DATA;
>> +        s->data_read_loop = true;
>> +        s->data[0] = 0;
>>           qemu_log_mask(LOG_GUEST_ERROR, "M25P80: Unknown cmd %x\n", value);
>>           break;
>>       }
>>
> 
> 

Re: [PATCH 1/3] m25p80: Convert to support tracing

[Guenter Roeck]

On 2/3/20 11:16 PM, Cédric Le Goater wrote:
> On 2/3/20 7:09 PM, Guenter Roeck wrote:
>> While at it, add some trace messages to help debug problems
>> seen when running the latest Linux kernel.
>>
>> Signed-off-by: Guenter Roeck <linux@roeck-us.net>
> 
> 
> Reviewed-by: Cédric Le Goater <clg@kaod.org>
> 
> We have been chasing a bug for years on the witherspoon-bmc machine
> using UBIfs. It will be useful.
> 
> What kind of issue are you looking at ?
> 

aspeed-ast2500-evb no longer boots from flash with the current mainline kernel.
The problem is fixed with the 3rd patch of the series.

Guenter

> Thanks,
> 
> C.
> 
>> ---
>>   hw/block/m25p80.c     | 48 ++++++++++++++++++++-----------------------
>>   hw/block/trace-events | 16 +++++++++++++++
>>   2 files changed, 38 insertions(+), 26 deletions(-)
>>
>> diff --git a/hw/block/m25p80.c b/hw/block/m25p80.c
>> index 11ff5b9ad7..63e050d7d3 100644
>> --- a/hw/block/m25p80.c
>> +++ b/hw/block/m25p80.c
>> @@ -32,17 +32,7 @@
>>   #include "qemu/module.h"
>>   #include "qemu/error-report.h"
>>   #include "qapi/error.h"
>> -
>> -#ifndef M25P80_ERR_DEBUG
>> -#define M25P80_ERR_DEBUG 0
>> -#endif
>> -
>> -#define DB_PRINT_L(level, ...) do { \
>> -    if (M25P80_ERR_DEBUG > (level)) { \
>> -        fprintf(stderr,  ": %s: ", __func__); \
>> -        fprintf(stderr, ## __VA_ARGS__); \
>> -    } \
>> -} while (0)
>> +#include "trace.h"
>>   
>>   /* Fields for FlashPartInfo->flags */
>>   
>> @@ -574,7 +564,8 @@ static void flash_erase(Flash *s, int offset, FlashCMD cmd)
>>           abort();
>>       }
>>   
>> -    DB_PRINT_L(0, "offset = %#x, len = %d\n", offset, len);
>> +    trace_m25p80_flash_erase(offset, len);
>> +
>>       if ((s->pi->flags & capa_to_assert) != capa_to_assert) {
>>           qemu_log_mask(LOG_GUEST_ERROR, "M25P80: %d erase size not supported by"
>>                         " device\n", len);
>> @@ -607,8 +598,7 @@ void flash_write8(Flash *s, uint32_t addr, uint8_t data)
>>       }
>>   
>>       if ((prev ^ data) & data) {
>> -        DB_PRINT_L(1, "programming zero to one! addr=%" PRIx32 "  %" PRIx8
>> -                   " -> %" PRIx8 "\n", addr, prev, data);
>> +        trace_m25p80_programming_zero_to_one(addr, prev, data);
>>       }
>>   
>>       if (s->pi->flags & EEPROM) {
>> @@ -662,6 +652,9 @@ static void complete_collecting_data(Flash *s)
>>   
>>       s->state = STATE_IDLE;
>>   
>> +    trace_m25p80_complete_collecting(s->cmd_in_progress, n, s->ear,
>> +                                     s->cur_addr);
>> +
>>       switch (s->cmd_in_progress) {
>>       case DPP:
>>       case QPP:
>> @@ -825,7 +818,7 @@ static void reset_memory(Flash *s)
>>           break;
>>       }
>>   
>> -    DB_PRINT_L(0, "Reset done.\n");
>> +    trace_m25p80_reset_done();
>>   }
>>   
>>   static void decode_fast_read_cmd(Flash *s)
>> @@ -941,9 +934,10 @@ static void decode_qio_read_cmd(Flash *s)
>>   
>>   static void decode_new_cmd(Flash *s, uint32_t value)
>>   {
>> -    s->cmd_in_progress = value;
>>       int i;
>> -    DB_PRINT_L(0, "decoded new command:%x\n", value);
>> +
>> +    s->cmd_in_progress = value;
>> +    trace_m25p80_command_decoded(value);
>>   
>>       if (value != RESET_MEMORY) {
>>           s->reset_enable = false;
>> @@ -1042,7 +1036,7 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>>           break;
>>   
>>       case JEDEC_READ:
>> -        DB_PRINT_L(0, "populated jedec code\n");
>> +        trace_m25p80_populated_jedec();
>>           for (i = 0; i < s->pi->id_len; i++) {
>>               s->data[i] = s->pi->id[i];
>>           }
>> @@ -1063,7 +1057,7 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>>       case BULK_ERASE_60:
>>       case BULK_ERASE:
>>           if (s->write_enable) {
>> -            DB_PRINT_L(0, "chip erase\n");
>> +            trace_m25p80_chip_erase();
>>               flash_erase(s, 0, BULK_ERASE);
>>           } else {
>>               qemu_log_mask(LOG_GUEST_ERROR, "M25P80: chip erase with write "
>> @@ -1184,7 +1178,7 @@ static int m25p80_cs(SSISlave *ss, bool select)
>>           s->data_read_loop = false;
>>       }
>>   
>> -    DB_PRINT_L(0, "%sselect\n", select ? "de" : "");
>> +    trace_m25p80_select(select ? "de" : "");
>>   
>>       return 0;
>>   }
>> @@ -1194,19 +1188,20 @@ static uint32_t m25p80_transfer8(SSISlave *ss, uint32_t tx)
>>       Flash *s = M25P80(ss);
>>       uint32_t r = 0;
>>   
>> +    trace_m25p80_transfer(s->state, s->len, s->needed_bytes, s->pos,
>> +                          s->cur_addr, (uint8_t)tx);
>> +
>>       switch (s->state) {
>>   
>>       case STATE_PAGE_PROGRAM:
>> -        DB_PRINT_L(1, "page program cur_addr=%#" PRIx32 " data=%" PRIx8 "\n",
>> -                   s->cur_addr, (uint8_t)tx);
>> +        trace_m25p80_page_program(s->cur_addr, (uint8_t)tx);
>>           flash_write8(s, s->cur_addr, (uint8_t)tx);
>>           s->cur_addr = (s->cur_addr + 1) & (s->size - 1);
>>           break;
>>   
>>       case STATE_READ:
>>           r = s->storage[s->cur_addr];
>> -        DB_PRINT_L(1, "READ 0x%" PRIx32 "=%" PRIx8 "\n", s->cur_addr,
>> -                   (uint8_t)r);
>> +        trace_m25p80_read_byte(s->cur_addr, (uint8_t)r);
>>           s->cur_addr = (s->cur_addr + 1) & (s->size - 1);
>>           break;
>>   
>> @@ -1244,6 +1239,7 @@ static uint32_t m25p80_transfer8(SSISlave *ss, uint32_t tx)
>>           }
>>   
>>           r = s->data[s->pos];
>> +        trace_m25p80_read_data(s->pos, (uint8_t)r);
>>           s->pos++;
>>           if (s->pos == s->len) {
>>               s->pos = 0;
>> @@ -1281,7 +1277,7 @@ static void m25p80_realize(SSISlave *ss, Error **errp)
>>               return;
>>           }
>>   
>> -        DB_PRINT_L(0, "Binding to IF_MTD drive\n");
>> +        trace_m25p80_binding();
>>           s->storage = blk_blockalign(s->blk, s->size);
>>   
>>           if (blk_pread(s->blk, 0, s->storage, s->size) != s->size) {
>> @@ -1289,7 +1285,7 @@ static void m25p80_realize(SSISlave *ss, Error **errp)
>>               return;
>>           }
>>       } else {
>> -        DB_PRINT_L(0, "No BDRV - binding to RAM\n");
>> +        trace_m25p80_binding_no_bdrv();
>>           s->storage = blk_blockalign(NULL, s->size);
>>           memset(s->storage, 0xFF, s->size);
>>       }
>> diff --git a/hw/block/trace-events b/hw/block/trace-events
>> index c03e80c2c9..d052f7578c 100644
>> --- a/hw/block/trace-events
>> +++ b/hw/block/trace-events
>> @@ -134,3 +134,19 @@ xen_block_blockdev_add(char *str) "%s"
>>   xen_block_blockdev_del(const char *node_name) "%s"
>>   xen_block_device_create(unsigned int number) "%u"
>>   xen_block_device_destroy(unsigned int number) "%u"
>> +
>> +# m25p80.c
>> +m25p80_flash_erase(int offset, uint32_t len) "offset = 0x%"PRIx32", len = %u"
>> +m25p80_programming_zero_to_one(uint32_t addr, uint8_t prev, uint8_t data) "programming zero to one! addr=0x%"PRIx32"  0x%"PRIx8" -> 0x%"PRIx8
>> +m25p80_reset_done(void) "Reset done."
>> +m25p80_command_decoded(uint32_t cmd) "new command:0x%"PRIx32
>> +m25p80_complete_collecting(uint32_t cmd, int n, uint8_t ear, uint32_t cur_addr) "decode cmd: 0x%"PRIx32" len %d ear 0x%"PRIx8" addr 0x%"PRIx32
>> +m25p80_populated_jedec(void) "populated jedec code"
>> +m25p80_chip_erase(void) "chip erase"
>> +m25p80_select(const char *what) "%sselect"
>> +m25p80_page_program(uint32_t addr, uint8_t tx) "page program cur_addr=0x%"PRIx32" data=0x%"PRIx8
>> +m25p80_transfer(uint8_t state, uint32_t len, uint8_t needed, uint32_t pos, uint32_t cur_addr, uint8_t t) "Transfer state 0x%"PRIx8" len 0x%"PRIx32" needed 0x%"PRIx8" pos 0x%"PRIx32" addr 0x%"PRIx32" tx 0x%"PRIx8
>> +m25p80_read_byte(uint32_t addr, uint8_t v) "Read byte 0x%"PRIx32"=0x%"PRIx8
>> +m25p80_read_data(uint32_t pos, uint8_t v) "Read data 0x%"PRIx32"=0x%"PRIx8
>> +m25p80_binding(void) "Binding to IF_MTD drive"
>> +m25p80_binding_no_bdrv(void) "No BDRV - binding to RAM"
>>
> 

Re: [PATCH 3/3] aspeed/smc: Fix number of dummy cycles for FAST_READ_4 command

[Guenter Roeck]

On 2/3/20 11:45 PM, Cédric Le Goater wrote:
> On 2/3/20 7:09 PM, Guenter Roeck wrote:
>> The Linux kernel recently started using FAST_READ_4 commands.
>> This results in flash read failures. At the same time, the m25p80
>> emulation is seen to read 8 more bytes than expected. Adjusting the
>> expected number of dummy cycles to match FAST_READ fixes the problem.
> 
> Which machine are you using for these tests ? the AST2500 evb using
> the w25q256 flash model ?
> 

Correct.

Guenter

> Any how, it looks correct.
> 
> Reviewed-by: Cédric Le Goater <clg@kaod.org>
> Fixes: f95c4bffdc4c ("aspeed/smc: snoop SPI transfers to fake dummy cycles")
> 
> I think commit ef06ca3946e2 ("xilinx_spips: Add support for RX discard
> and RX drain") needs a similar fix. Adding Francisco.
> 
> Thanks,
> 
> C.
> 
> 
>> Signed-off-by: Guenter Roeck <linux@roeck-us.net>
>> ---
>>   hw/ssi/aspeed_smc.c | 2 +-
>>   1 file changed, 1 insertion(+), 1 deletion(-)
>>
>> diff --git a/hw/ssi/aspeed_smc.c b/hw/ssi/aspeed_smc.c
>> index f0c7bbbad3..61e8fa57d3 100644
>> --- a/hw/ssi/aspeed_smc.c
>> +++ b/hw/ssi/aspeed_smc.c
>> @@ -762,11 +762,11 @@ static int aspeed_smc_num_dummies(uint8_t command)
>>       case FAST_READ:
>>       case DOR:
>>       case QOR:
>> +    case FAST_READ_4:
>>       case DOR_4:
>>       case QOR_4:
>>           return 1;
>>       case DIOR:
>> -    case FAST_READ_4:
>>       case DIOR_4:
>>           return 2;
>>       case QIOR:
>>
> 

Re: [PATCH 2/3] m25p80: Improve command handling for Jedec and unsupported commands

[Guenter Roeck]

On 2/4/20 12:53 AM, Cédric Le Goater wrote:
> On 2/3/20 7:09 PM, Guenter Roeck wrote:
>> Always report 6 bytes of JEDEC data. Fill remaining data with 0.
>>
>> For unsupported commands, keep sending a value of 0 until the chip
>> is deselected.
>>
>> Both changes avoid attempts to decode random commands. Up to now this
>> happened if the reported Jedec data was shorter than 6 bytes but the
>> host read 6 bytes, and with all unsupported commands.
> 
> Do you have a concrete example for that ? machine and flash model.
> 

I noticed it while tracking down the bug fixed in patch 3 of the series,
ie with AST2500 evb using w25q256 flash, but it happens with all machines
using SPI NOR flash (ie all aspeed bmc machines) when running the Linux
kernel. Most of the time it doesn't cause harm, unless the host sends
an "address" as part of an unsupported command which happens to include
a valid command code.

>> Signed-off-by: Guenter Roeck <linux@roeck-us.net>
>> ---
>>   hw/block/m25p80.c | 10 +++++++++-
>>   1 file changed, 9 insertions(+), 1 deletion(-)
>>
>> diff --git a/hw/block/m25p80.c b/hw/block/m25p80.c
>> index 63e050d7d3..aca75edcc1 100644
>> --- a/hw/block/m25p80.c
>> +++ b/hw/block/m25p80.c
>> @@ -1040,8 +1040,11 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>>           for (i = 0; i < s->pi->id_len; i++) {
>>               s->data[i] = s->pi->id[i];
>>           }
>> +        for (; i < SPI_NOR_MAX_ID_LEN; i++) {
>> +            s->data[i] = 0;
>> +        }
> 
> It seems that data should be reseted in m25p80_cs() also.
> 
Are you sure ?

The current implementation sets s->data[] as needed when command decode
is complete. That seems less costly to me.

Thanks,
Guenter

>>   
>> -        s->len = s->pi->id_len;
>> +        s->len = SPI_NOR_MAX_ID_LEN;
>>           s->pos = 0;
>>           s->state = STATE_READING_DATA;
>>           break;
>> @@ -1158,6 +1161,11 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>>           s->quad_enable = false;
>>           break;
>>       default:
>> +        s->pos = 0;
>> +        s->len = 1;
>> +        s->state = STATE_READING_DATA;
>> +        s->data_read_loop = true;
>> +        s->data[0] = 0;
>>           qemu_log_mask(LOG_GUEST_ERROR, "M25P80: Unknown cmd %x\n", value);
>>           break;
>>       }
>>
> 

Re: [PATCH 1/3] m25p80: Convert to support tracing

[Cédric Le Goater]

On 2/3/20 7:09 PM, Guenter Roeck wrote:
> While at it, add some trace messages to help debug problems
> seen when running the latest Linux kernel.

In case you resend, It would be nice to printout a flash id in the tracing
else I have a patch for it on top of yours. It helped me track a squashfs
corruption on the Aspeed witherspoon-bmc machine which we were after since
2017 or so. It seems to be a kernel bug.

Thanks,

C. 

> Signed-off-by: Guenter Roeck <linux@roeck-us.net>
> ---
>  hw/block/m25p80.c     | 48 ++++++++++++++++++++-----------------------
>  hw/block/trace-events | 16 +++++++++++++++
>  2 files changed, 38 insertions(+), 26 deletions(-)
> 
> diff --git a/hw/block/m25p80.c b/hw/block/m25p80.c
> index 11ff5b9ad7..63e050d7d3 100644
> --- a/hw/block/m25p80.c
> +++ b/hw/block/m25p80.c
> @@ -32,17 +32,7 @@
>  #include "qemu/module.h"
>  #include "qemu/error-report.h"
>  #include "qapi/error.h"
> -
> -#ifndef M25P80_ERR_DEBUG
> -#define M25P80_ERR_DEBUG 0
> -#endif
> -
> -#define DB_PRINT_L(level, ...) do { \
> -    if (M25P80_ERR_DEBUG > (level)) { \
> -        fprintf(stderr,  ": %s: ", __func__); \
> -        fprintf(stderr, ## __VA_ARGS__); \
> -    } \
> -} while (0)
> +#include "trace.h"
>  
>  /* Fields for FlashPartInfo->flags */
>  
> @@ -574,7 +564,8 @@ static void flash_erase(Flash *s, int offset, FlashCMD cmd)
>          abort();
>      }
>  
> -    DB_PRINT_L(0, "offset = %#x, len = %d\n", offset, len);
> +    trace_m25p80_flash_erase(offset, len);
> +
>      if ((s->pi->flags & capa_to_assert) != capa_to_assert) {
>          qemu_log_mask(LOG_GUEST_ERROR, "M25P80: %d erase size not supported by"
>                        " device\n", len);
> @@ -607,8 +598,7 @@ void flash_write8(Flash *s, uint32_t addr, uint8_t data)
>      }
>  
>      if ((prev ^ data) & data) {
> -        DB_PRINT_L(1, "programming zero to one! addr=%" PRIx32 "  %" PRIx8
> -                   " -> %" PRIx8 "\n", addr, prev, data);
> +        trace_m25p80_programming_zero_to_one(addr, prev, data);
>      }
>  
>      if (s->pi->flags & EEPROM) {
> @@ -662,6 +652,9 @@ static void complete_collecting_data(Flash *s)
>  
>      s->state = STATE_IDLE;
>  
> +    trace_m25p80_complete_collecting(s->cmd_in_progress, n, s->ear,
> +                                     s->cur_addr);
> +
>      switch (s->cmd_in_progress) {
>      case DPP:
>      case QPP:
> @@ -825,7 +818,7 @@ static void reset_memory(Flash *s)
>          break;
>      }
>  
> -    DB_PRINT_L(0, "Reset done.\n");
> +    trace_m25p80_reset_done();
>  }
>  
>  static void decode_fast_read_cmd(Flash *s)
> @@ -941,9 +934,10 @@ static void decode_qio_read_cmd(Flash *s)
>  
>  static void decode_new_cmd(Flash *s, uint32_t value)
>  {
> -    s->cmd_in_progress = value;
>      int i;
> -    DB_PRINT_L(0, "decoded new command:%x\n", value);
> +
> +    s->cmd_in_progress = value;
> +    trace_m25p80_command_decoded(value);
>  
>      if (value != RESET_MEMORY) {
>          s->reset_enable = false;
> @@ -1042,7 +1036,7 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>          break;
>  
>      case JEDEC_READ:
> -        DB_PRINT_L(0, "populated jedec code\n");
> +        trace_m25p80_populated_jedec();
>          for (i = 0; i < s->pi->id_len; i++) {
>              s->data[i] = s->pi->id[i];
>          }
> @@ -1063,7 +1057,7 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>      case BULK_ERASE_60:
>      case BULK_ERASE:
>          if (s->write_enable) {
> -            DB_PRINT_L(0, "chip erase\n");
> +            trace_m25p80_chip_erase();
>              flash_erase(s, 0, BULK_ERASE);
>          } else {
>              qemu_log_mask(LOG_GUEST_ERROR, "M25P80: chip erase with write "
> @@ -1184,7 +1178,7 @@ static int m25p80_cs(SSISlave *ss, bool select)
>          s->data_read_loop = false;
>      }
>  
> -    DB_PRINT_L(0, "%sselect\n", select ? "de" : "");
> +    trace_m25p80_select(select ? "de" : "");
>  
>      return 0;
>  }
> @@ -1194,19 +1188,20 @@ static uint32_t m25p80_transfer8(SSISlave *ss, uint32_t tx)
>      Flash *s = M25P80(ss);
>      uint32_t r = 0;
>  
> +    trace_m25p80_transfer(s->state, s->len, s->needed_bytes, s->pos,
> +                          s->cur_addr, (uint8_t)tx);
> +
>      switch (s->state) {
>  
>      case STATE_PAGE_PROGRAM:
> -        DB_PRINT_L(1, "page program cur_addr=%#" PRIx32 " data=%" PRIx8 "\n",
> -                   s->cur_addr, (uint8_t)tx);
> +        trace_m25p80_page_program(s->cur_addr, (uint8_t)tx);
>          flash_write8(s, s->cur_addr, (uint8_t)tx);
>          s->cur_addr = (s->cur_addr + 1) & (s->size - 1);
>          break;
>  
>      case STATE_READ:
>          r = s->storage[s->cur_addr];
> -        DB_PRINT_L(1, "READ 0x%" PRIx32 "=%" PRIx8 "\n", s->cur_addr,
> -                   (uint8_t)r);
> +        trace_m25p80_read_byte(s->cur_addr, (uint8_t)r);
>          s->cur_addr = (s->cur_addr + 1) & (s->size - 1);
>          break;
>  
> @@ -1244,6 +1239,7 @@ static uint32_t m25p80_transfer8(SSISlave *ss, uint32_t tx)
>          }
>  
>          r = s->data[s->pos];
> +        trace_m25p80_read_data(s->pos, (uint8_t)r);
>          s->pos++;
>          if (s->pos == s->len) {
>              s->pos = 0;
> @@ -1281,7 +1277,7 @@ static void m25p80_realize(SSISlave *ss, Error **errp)
>              return;
>          }
>  
> -        DB_PRINT_L(0, "Binding to IF_MTD drive\n");
> +        trace_m25p80_binding();
>          s->storage = blk_blockalign(s->blk, s->size);
>  
>          if (blk_pread(s->blk, 0, s->storage, s->size) != s->size) {
> @@ -1289,7 +1285,7 @@ static void m25p80_realize(SSISlave *ss, Error **errp)
>              return;
>          }
>      } else {
> -        DB_PRINT_L(0, "No BDRV - binding to RAM\n");
> +        trace_m25p80_binding_no_bdrv();
>          s->storage = blk_blockalign(NULL, s->size);
>          memset(s->storage, 0xFF, s->size);
>      }
> diff --git a/hw/block/trace-events b/hw/block/trace-events
> index c03e80c2c9..d052f7578c 100644
> --- a/hw/block/trace-events
> +++ b/hw/block/trace-events
> @@ -134,3 +134,19 @@ xen_block_blockdev_add(char *str) "%s"
>  xen_block_blockdev_del(const char *node_name) "%s"
>  xen_block_device_create(unsigned int number) "%u"
>  xen_block_device_destroy(unsigned int number) "%u"
> +
> +# m25p80.c
> +m25p80_flash_erase(int offset, uint32_t len) "offset = 0x%"PRIx32", len = %u"
> +m25p80_programming_zero_to_one(uint32_t addr, uint8_t prev, uint8_t data) "programming zero to one! addr=0x%"PRIx32"  0x%"PRIx8" -> 0x%"PRIx8
> +m25p80_reset_done(void) "Reset done."
> +m25p80_command_decoded(uint32_t cmd) "new command:0x%"PRIx32
> +m25p80_complete_collecting(uint32_t cmd, int n, uint8_t ear, uint32_t cur_addr) "decode cmd: 0x%"PRIx32" len %d ear 0x%"PRIx8" addr 0x%"PRIx32
> +m25p80_populated_jedec(void) "populated jedec code"
> +m25p80_chip_erase(void) "chip erase"
> +m25p80_select(const char *what) "%sselect"
> +m25p80_page_program(uint32_t addr, uint8_t tx) "page program cur_addr=0x%"PRIx32" data=0x%"PRIx8
> +m25p80_transfer(uint8_t state, uint32_t len, uint8_t needed, uint32_t pos, uint32_t cur_addr, uint8_t t) "Transfer state 0x%"PRIx8" len 0x%"PRIx32" needed 0x%"PRIx8" pos 0x%"PRIx32" addr 0x%"PRIx32" tx 0x%"PRIx8
> +m25p80_read_byte(uint32_t addr, uint8_t v) "Read byte 0x%"PRIx32"=0x%"PRIx8
> +m25p80_read_data(uint32_t pos, uint8_t v) "Read data 0x%"PRIx32"=0x%"PRIx8
> +m25p80_binding(void) "Binding to IF_MTD drive"
> +m25p80_binding_no_bdrv(void) "No BDRV - binding to RAM"
> 

Re: [PATCH 2/3] m25p80: Improve command handling for Jedec and unsupported commands

[Cédric Le Goater]

On 2/4/20 3:28 PM, Guenter Roeck wrote:
> On 2/4/20 12:53 AM, Cédric Le Goater wrote:
>> On 2/3/20 7:09 PM, Guenter Roeck wrote:
>>> Always report 6 bytes of JEDEC data. Fill remaining data with 0.
>>>
>>> For unsupported commands, keep sending a value of 0 until the chip
>>> is deselected.
>>>
>>> Both changes avoid attempts to decode random commands. Up to now this
>>> happened if the reported Jedec data was shorter than 6 bytes but the
>>> host read 6 bytes, and with all unsupported commands.
>>
>> Do you have a concrete example for that ? machine and flash model.
>>
> 
> I noticed it while tracking down the bug fixed in patch 3 of the series,
> ie with AST2500 evb using w25q256 flash, but it happens with all machines
> using SPI NOR flash (ie all aspeed bmc machines) when running the Linux
> kernel. Most of the time it doesn't cause harm, unless the host sends
> an "address" as part of an unsupported command which happens to include
> a valid command code.

ok. we will need to model SFDP one day.

Are you using the OpenBMC images or do you have your own ? 

> 
>>> Signed-off-by: Guenter Roeck <linux@roeck-us.net>
>>> ---
>>>   hw/block/m25p80.c | 10 +++++++++-
>>>   1 file changed, 9 insertions(+), 1 deletion(-)
>>>
>>> diff --git a/hw/block/m25p80.c b/hw/block/m25p80.c
>>> index 63e050d7d3..aca75edcc1 100644
>>> --- a/hw/block/m25p80.c
>>> +++ b/hw/block/m25p80.c
>>> @@ -1040,8 +1040,11 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>>>           for (i = 0; i < s->pi->id_len; i++) {
>>>               s->data[i] = s->pi->id[i];
>>>           }
>>> +        for (; i < SPI_NOR_MAX_ID_LEN; i++) {
>>> +            s->data[i] = 0;
>>> +        }
>>
>> It seems that data should be reseted in m25p80_cs() also.
>>
> Are you sure ?
> 
> The current implementation sets s->data[] as needed when command decode
> is complete. That seems less costly to me.

ok.
Reviewed-by: Cédric Le Goater <clg@kaod.org>


Thanks,

C.
 
> Thanks,
> Guenter
> 
>>>   -        s->len = s->pi->id_len;
>>> +        s->len = SPI_NOR_MAX_ID_LEN;
>>>           s->pos = 0;
>>>           s->state = STATE_READING_DATA;
>>>           break;
>>> @@ -1158,6 +1161,11 @@ static void decode_new_cmd(Flash *s, uint32_t value)
>>>           s->quad_enable = false;
>>>           break;
>>>       default:
>>> +        s->pos = 0;
>>> +        s->len = 1;
>>> +        s->state = STATE_READING_DATA;
>>> +        s->data_read_loop = true;
>>> +        s->data[0] = 0;
>>>           qemu_log_mask(LOG_GUEST_ERROR, "M25P80: Unknown cmd %x\n", value);
>>>           break;
>>>       }
>>>
>>
> 

Re: [PATCH 1/3] m25p80: Convert to support tracing

[Guenter Roeck]

On Wed, Feb 05, 2020 at 11:05:04AM +0100, Cédric Le Goater wrote:
> On 2/3/20 7:09 PM, Guenter Roeck wrote:
> > While at it, add some trace messages to help debug problems
> > seen when running the latest Linux kernel.
> 
> In case you resend, It would be nice to printout a flash id in the tracing
> else I have a patch for it on top of yours. It helped me track a squashfs
> corruption on the Aspeed witherspoon-bmc machine which we were after since
> 2017 or so. It seems to be a kernel bug.
> 

I'll send a new version to split patch 2. Not sure I understand what you mean
with the above. If you send me your patch I'll be happy to merge it into mine,
otherwise we can just keep it as follow-ip patch.

Thanks,
Guenter

Re: [PATCH 1/3] m25p80: Convert to support tracing

[Cédric Le Goater]

On 2/5/20 5:35 PM, Guenter Roeck wrote:
> On Wed, Feb 05, 2020 at 11:05:04AM +0100, Cédric Le Goater wrote:
>> On 2/3/20 7:09 PM, Guenter Roeck wrote:
>>> While at it, add some trace messages to help debug problems
>>> seen when running the latest Linux kernel.
>>
>> In case you resend, It would be nice to printout a flash id in the tracing
>> else I have a patch for it on top of yours. It helped me track a squashfs
>> corruption on the Aspeed witherspoon-bmc machine which we were after since
>> 2017 or so. It seems to be a kernel bug.
>>
> 
> I'll send a new version to split patch 2. Not sure I understand what you mean
> with the above. If you send me your patch I'll be happy to merge it into mine,
> otherwise we can just keep it as follow-ip patch.

Here is the idea : 

  https://github.com/legoater/qemu/commit/a07727e9cfc8447ea18249ff68a561f7e8883584

You can merge and maybe extend to all traces.


In the issue we had, two CS could be selected at the same time 
and the SPI transfers were getting mixed. Printing out which
CS is doing what is interesting for debug. 

Thanks,
C.

Re: [PATCH 2/3] m25p80: Improve command handling for Jedec and unsupported commands

[Guenter Roeck]

On Wed, Feb 05, 2020 at 11:08:07AM +0100, Cédric Le Goater wrote:
> On 2/4/20 3:28 PM, Guenter Roeck wrote:
> > On 2/4/20 12:53 AM, Cédric Le Goater wrote:
> >> On 2/3/20 7:09 PM, Guenter Roeck wrote:
> >>> Always report 6 bytes of JEDEC data. Fill remaining data with 0.
> >>>
> >>> For unsupported commands, keep sending a value of 0 until the chip
> >>> is deselected.
> >>>
> >>> Both changes avoid attempts to decode random commands. Up to now this
> >>> happened if the reported Jedec data was shorter than 6 bytes but the
> >>> host read 6 bytes, and with all unsupported commands.
> >>
> >> Do you have a concrete example for that ? machine and flash model.
> >>
> > 
> > I noticed it while tracking down the bug fixed in patch 3 of the series,
> > ie with AST2500 evb using w25q256 flash, but it happens with all machines
> > using SPI NOR flash (ie all aspeed bmc machines) when running the Linux
> > kernel. Most of the time it doesn't cause harm, unless the host sends
> > an "address" as part of an unsupported command which happens to include
> > a valid command code.
> 
> ok. we will need to model SFDP one day.
> 
> Are you using the OpenBMC images or do you have your own ? 
> 

I am running images built from upstream/stable kernel branches.

Guenter

> > 
> >>> Signed-off-by: Guenter Roeck <linux@roeck-us.net>
> >>> ---
> >>>   hw/block/m25p80.c | 10 +++++++++-
> >>>   1 file changed, 9 insertions(+), 1 deletion(-)
> >>>
> >>> diff --git a/hw/block/m25p80.c b/hw/block/m25p80.c
> >>> index 63e050d7d3..aca75edcc1 100644
> >>> --- a/hw/block/m25p80.c
> >>> +++ b/hw/block/m25p80.c
> >>> @@ -1040,8 +1040,11 @@ static void decode_new_cmd(Flash *s, uint32_t value)
> >>>           for (i = 0; i < s->pi->id_len; i++) {
> >>>               s->data[i] = s->pi->id[i];
> >>>           }
> >>> +        for (; i < SPI_NOR_MAX_ID_LEN; i++) {
> >>> +            s->data[i] = 0;
> >>> +        }
> >>
> >> It seems that data should be reseted in m25p80_cs() also.
> >>
> > Are you sure ?
> > 
> > The current implementation sets s->data[] as needed when command decode
> > is complete. That seems less costly to me.
> 
> ok.
> Reviewed-by: Cédric Le Goater <clg@kaod.org>
> 
> 
> Thanks,
> 
> C.
>  
> > Thanks,
> > Guenter
> > 
> >>>   -        s->len = s->pi->id_len;
> >>> +        s->len = SPI_NOR_MAX_ID_LEN;
> >>>           s->pos = 0;
> >>>           s->state = STATE_READING_DATA;
> >>>           break;
> >>> @@ -1158,6 +1161,11 @@ static void decode_new_cmd(Flash *s, uint32_t value)
> >>>           s->quad_enable = false;
> >>>           break;
> >>>       default:
> >>> +        s->pos = 0;
> >>> +        s->len = 1;
> >>> +        s->state = STATE_READING_DATA;
> >>> +        s->data_read_loop = true;
> >>> +        s->data[0] = 0;
> >>>           qemu_log_mask(LOG_GUEST_ERROR, "M25P80: Unknown cmd %x\n", value);
> >>>           break;
> >>>       }
> >>>
> >>
> > 
> 

Re: [PATCH 1/3] m25p80: Convert to support tracing

[Guenter Roeck]

On Wed, Feb 05, 2020 at 06:10:44PM +0100, Cédric Le Goater wrote:
> On 2/5/20 5:35 PM, Guenter Roeck wrote:
> > On Wed, Feb 05, 2020 at 11:05:04AM +0100, Cédric Le Goater wrote:
> >> On 2/3/20 7:09 PM, Guenter Roeck wrote:
> >>> While at it, add some trace messages to help debug problems
> >>> seen when running the latest Linux kernel.
> >>
> >> In case you resend, It would be nice to printout a flash id in the tracing
> >> else I have a patch for it on top of yours. It helped me track a squashfs
> >> corruption on the Aspeed witherspoon-bmc machine which we were after since
> >> 2017 or so. It seems to be a kernel bug.
> >>
> > 
> > I'll send a new version to split patch 2. Not sure I understand what you mean
> > with the above. If you send me your patch I'll be happy to merge it into mine,
> > otherwise we can just keep it as follow-ip patch.
> 
> Here is the idea : 
> 
>   https://github.com/legoater/qemu/commit/a07727e9cfc8447ea18249ff68a561f7e8883584
> 

Ah, that. I had thought about doing that, but I found displaying the pointer
a bit clumsy. It looks like there isn't really anything else available that
would provide a flash index, and I agree that it would be useful, so I'll
add it for all traces.

Thanks,
Guenter

Re: [PATCH 2/3] m25p80: Improve command handling for Jedec and unsupported commands

[Joel Stanley]

On Wed, 5 Feb 2020 at 17:43, Guenter Roeck <linux@roeck-us.net> wrote:
>
> On Wed, Feb 05, 2020 at 11:08:07AM +0100, Cédric Le Goater wrote:
> >
> > ok. we will need to model SFDP one day.
> >
> > Are you using the OpenBMC images or do you have your own ?
> >
>
> I am running images built from upstream/stable kernel branches.

I think Cédric was wondering which flash images and therefore
filesystems you were using in your testing.

I had a poke around here but I couldn't work out where 'mtd32' came from:

https://github.com/groeck/linux-build-test/blob/master/rootfs/arm/run-qemu-arm.sh

Cheers,

Joel

Re: [PATCH 2/3] m25p80: Improve command handling for Jedec and unsupported commands

[Guenter Roeck]

On 2/5/20 11:04 PM, Joel Stanley wrote:
> On Wed, 5 Feb 2020 at 17:43, Guenter Roeck <linux@roeck-us.net> wrote:
>>
>> On Wed, Feb 05, 2020 at 11:08:07AM +0100, Cédric Le Goater wrote:
>>>
>>> ok. we will need to model SFDP one day.
>>>
>>> Are you using the OpenBMC images or do you have your own ?
>>>
>>
>> I am running images built from upstream/stable kernel branches.
> 
> I think Cédric was wondering which flash images and therefore
> filesystems you were using in your testing.
> 
Ah, ok. Sorry, misunderstood.

> I had a poke around here but I couldn't work out where 'mtd32' came from:
> 
> https://github.com/groeck/linux-build-test/blob/master/rootfs/arm/run-qemu-arm.sh
> 

mtd32 tells the infrastructure that the boot device is mtd (flash) with
32MB capacity. The infrastructure uses that to create the actual flash
image and to generate the qemu command line. The root file system is
is rootfs-armv5.ext2 (located in the same directory as the run script).
It was generated using buildroot.

Guenter

Re: [PATCH 3/3] aspeed/smc: Fix number of dummy cycles for FAST_READ_4 command

[Francisco Iglesias]

Hi Cédric,

On [2020 Feb 04] Tue 08:45:11, Cédric Le Goater wrote:
> On 2/3/20 7:09 PM, Guenter Roeck wrote:
> > The Linux kernel recently started using FAST_READ_4 commands.
> > This results in flash read failures. At the same time, the m25p80
> > emulation is seen to read 8 more bytes than expected. Adjusting the
> > expected number of dummy cycles to match FAST_READ fixes the problem.
> 
> Which machine are you using for these tests ? the AST2500 evb using
> the w25q256 flash model ? 
> 
> Any how, it looks correct. 
> 
> Reviewed-by: Cédric Le Goater <clg@kaod.org>
> Fixes: f95c4bffdc4c ("aspeed/smc: snoop SPI transfers to fake dummy cycles")
> 
> I think commit ef06ca3946e2 ("xilinx_spips: Add support for RX discard 
> and RX drain") needs a similar fix. Adding Francisco.

Yes, I agree that a similar fix is needed in the xilinx_spips aswell, I just
provided a patch. Thank you for the notification!

Best regards,
Francisco Iglesias

> 
> Thanks,
> 
> C. 
> 
> 
> > Signed-off-by: Guenter Roeck <linux@roeck-us.net>
> > ---
> >  hw/ssi/aspeed_smc.c | 2 +-
> >  1 file changed, 1 insertion(+), 1 deletion(-)
> > 
> > diff --git a/hw/ssi/aspeed_smc.c b/hw/ssi/aspeed_smc.c
> > index f0c7bbbad3..61e8fa57d3 100644
> > --- a/hw/ssi/aspeed_smc.c
> > +++ b/hw/ssi/aspeed_smc.c
> > @@ -762,11 +762,11 @@ static int aspeed_smc_num_dummies(uint8_t command)
> >      case FAST_READ:
> >      case DOR:
> >      case QOR:
> > +    case FAST_READ_4:
> >      case DOR_4:
> >      case QOR_4:
> >          return 1;
> >      case DIOR:
> > -    case FAST_READ_4:
> >      case DIOR_4:
> >          return 2;
> >      case QIOR:
> > 
>